Skip to content

Pooler error with auth_type = hba #118

Description

@grayhemp

Ubuntu 14.04
PgBouncer 1.7.2

pgbouncer.ini

[databases]
xyz = host=127.0.0.1 port=5432 dbname=xyz auth_user=postgres

listen_addr = *
listen_port = 6432

auth_type = hba
auth_file = /etc/pgbouncer/userlist.txt
auth_hba_file = /etc/postgresql/9.0/report/pg_hba.conf
auth_query = SELECT usename, passwd FROM pg_shadow WHERE usename=$1

pg_hba.conf

...
host    all             all             127.0.0.1/32            md5
...

When trying to connect

psql -h 127.0.0.1 -p 6432 -U xyz xyz

getting a pooler error

root@db:~# pgbouncer -u postgres /etc/pgbouncer/pgbouncer.ini -vv
2016-03-04 16:08:52.801 99616 DEBUG parse_ini_file: [databases]
2016-03-04 16:08:52.801 99616 DEBUG parse_ini_file: 'xyz' = 'host=127.0.0.1 port=5432 dbname=xyz auth_user=postgres'
2016-03-04 16:08:52.801 99616 NOISE cstr_get_pair: "host"="127.0.0.1"
2016-03-04 16:08:52.801 99616 NOISE cstr_get_pair: "port"="5432"
2016-03-04 16:08:52.801 99616 NOISE cstr_get_pair: "dbname"="xyz"
2016-03-04 16:08:52.801 99616 NOISE cstr_get_pair: "auth_user"="postgres"
2016-03-04 16:08:52.801 99616 DEBUG pktbuf_dynamic(128): 0x14f7580
2016-03-04 16:08:52.801 99616 DEBUG parse_ini_file: 'xyz' = 'host=127.0.0.1 port=5432 dbname=xyz auth_user=postgres' ok:1
2016-03-04 16:08:52.801 99616 DEBUG parse_ini_file: [pgbouncer]
2016-03-04 16:08:52.801 99616 DEBUG parse_ini_file: 'logfile' = '/var/log/postgresql/pgbouncer.log'
2016-03-04 16:08:52.801 99616 DEBUG parse_ini_file: 'logfile' = '/var/log/postgresql/pgbouncer.log' ok:1
2016-03-04 16:08:52.801 99616 DEBUG parse_ini_file: 'pidfile' = '/var/run/postgresql/pgbouncer.pid'
2016-03-04 16:08:52.801 99616 DEBUG parse_ini_file: 'pidfile' = '/var/run/postgresql/pgbouncer.pid' ok:1
2016-03-04 16:08:52.801 99616 DEBUG parse_ini_file: 'listen_addr' = '*'
2016-03-04 16:08:52.801 99616 DEBUG parse_ini_file: 'listen_addr' = '*' ok:1
2016-03-04 16:08:52.801 99616 DEBUG parse_ini_file: 'listen_port' = '6432'
2016-03-04 16:08:52.801 99616 DEBUG parse_ini_file: 'listen_port' = '6432' ok:1
2016-03-04 16:08:52.801 99616 DEBUG parse_ini_file: 'unix_socket_dir' = '/var/run/postgresql'
2016-03-04 16:08:52.802 99616 DEBUG parse_ini_file: 'unix_socket_dir' = '/var/run/postgresql' ok:1
2016-03-04 16:08:52.802 99616 DEBUG parse_ini_file: 'auth_type' = 'hba'
2016-03-04 16:08:52.802 99616 DEBUG parse_ini_file: 'auth_type' = 'hba' ok:1
2016-03-04 16:08:52.802 99616 DEBUG parse_ini_file: 'auth_file' = '/etc/pgbouncer/userlist.txt'
2016-03-04 16:08:52.802 99616 DEBUG parse_ini_file: 'auth_file' = '/etc/pgbouncer/userlist.txt' ok:1
2016-03-04 16:08:52.802 99616 DEBUG parse_ini_file: 'auth_hba_file' = '/etc/postgresql/9.0/report/pg_hba.conf'
2016-03-04 16:08:52.802 99616 DEBUG parse_ini_file: 'auth_hba_file' = '/etc/postgresql/9.0/report/pg_hba.conf' ok:1
2016-03-04 16:08:52.802 99616 DEBUG parse_ini_file: 'auth_query' = 'SELECT usename, passwd FROM pg_shadow WHERE usename=$1'
2016-03-04 16:08:52.802 99616 DEBUG parse_ini_file: 'auth_query' = 'SELECT usename, passwd FROM pg_shadow WHERE usename=$1' ok:1
2016-03-04 16:08:52.802 99616 DEBUG parse_ini_file: 'admin_users' = 'postgres, pgbadmin'
2016-03-04 16:08:52.802 99616 DEBUG parse_ini_file: 'admin_users' = 'postgres, pgbadmin' ok:1
2016-03-04 16:08:52.802 99616 DEBUG parse_ini_file: 'stats_users' = 'postgres, pgb_stat_collector'
2016-03-04 16:08:52.802 99616 DEBUG parse_ini_file: 'stats_users' = 'postgres, pgb_stat_collector' ok:1
2016-03-04 16:08:52.802 99616 DEBUG parse_ini_file: 'pool_mode' = 'transaction'
2016-03-04 16:08:52.802 99616 DEBUG parse_ini_file: 'pool_mode' = 'transaction' ok:1
2016-03-04 16:08:52.802 99616 DEBUG parse_ini_file: 'server_reset_query' = ''
2016-03-04 16:08:52.802 99616 DEBUG parse_ini_file: 'server_reset_query' = '' ok:1
2016-03-04 16:08:52.802 99616 DEBUG parse_ini_file: 'ignore_startup_parameters' = 'extra_float_digits'
2016-03-04 16:08:52.802 99616 DEBUG parse_ini_file: 'ignore_startup_parameters' = 'extra_float_digits' ok:1
2016-03-04 16:08:52.802 99616 DEBUG parse_ini_file: 'max_client_conn' = '10000'
2016-03-04 16:08:52.802 99616 DEBUG parse_ini_file: 'max_client_conn' = '10000' ok:1
2016-03-04 16:08:52.802 99616 DEBUG parse_ini_file: 'default_pool_size' = '40'
2016-03-04 16:08:52.802 99616 DEBUG parse_ini_file: 'default_pool_size' = '40' ok:1
2016-03-04 16:08:52.802 99616 DEBUG parse_ini_file: 'log_connections' = '0'
2016-03-04 16:08:52.802 99616 DEBUG parse_ini_file: 'log_connections' = '0' ok:1
2016-03-04 16:08:52.802 99616 DEBUG parse_ini_file: 'log_disconnections' = '0'
2016-03-04 16:08:52.802 99616 DEBUG parse_ini_file: 'log_disconnections' = '0' ok:1
2016-03-04 16:08:52.802 99616 DEBUG parse_ini_file: 'pkt_buf' = '524288'
2016-03-04 16:08:52.802 99616 DEBUG parse_ini_file: 'pkt_buf' = '524288' ok:1
2016-03-04 16:08:52.802 99616 DEBUG parse_ini_file: 'listen_backlog' = '20000'
2016-03-04 16:08:52.802 99616 DEBUG parse_ini_file: 'listen_backlog' = '20000' ok:1
2016-03-04 16:08:52.802 99616 DEBUG parse_ini_file: 'tcp_socket_buffer' = '8388608'
2016-03-04 16:08:52.802 99616 DEBUG parse_ini_file: 'tcp_socket_buffer' = '8388608' ok:1
2016-03-04 16:08:52.802 99616 DEBUG loading auth_file: "/etc/pgbouncer/userlist.txt"
2016-03-04 16:08:52.803 99616 WARNING hba line 81: unsupported method: buf=ident
2016-03-04 16:08:52.806 99616 NOISE event: 136, SBuf: 200, PgSocket: 392, IOBuf: 524300
2016-03-04 16:08:52.806 99616 LOG File descriptor limit: 655350 (H:655350), max_client_conn: 10000, max fds possible: 10130
2016-03-04 16:08:52.806 99616 DEBUG pktbuf_dynamic(128): 0x151f750
2016-03-04 16:08:52.806 99616 DEBUG make_room(0x151f750, 9): realloc newlen=256
2016-03-04 16:08:52.806 99616 DEBUG pktbuf_dynamic(128): 0x151f930
2016-03-04 16:08:52.806 99616 NOISE connect(5, unix:/var/run/postgresql/.s.PGSQL.6432) = No such file or directory
2016-03-04 16:08:52.807 99616 DEBUG adns_create_context: evdns2
2016-03-04 16:08:52.807 99616 DEBUG add_listen: 0.0.0.0:6432
2016-03-04 16:08:52.807 99616 NOISE old TCP_DEFER_ACCEPT on 10 = 0
2016-03-04 16:08:52.807 99616 NOISE install TCP_DEFER_ACCEPT on 10
2016-03-04 16:08:52.807 99616 LOG listening on 0.0.0.0:6432
2016-03-04 16:08:52.807 99616 DEBUG add_listen: ::/6432
2016-03-04 16:08:52.807 99616 NOISE old TCP_DEFER_ACCEPT on 11 = 0
2016-03-04 16:08:52.807 99616 NOISE install TCP_DEFER_ACCEPT on 11
2016-03-04 16:08:52.807 99616 LOG listening on ::/6432
2016-03-04 16:08:52.807 99616 DEBUG add_listen: unix:/var/run/postgresql/.s.PGSQL.6432
2016-03-04 16:08:52.807 99616 LOG listening on unix:/var/run/postgresql/.s.PGSQL.6432
2016-03-04 16:08:52.807 99616 LOG process up: pgbouncer 1.7.2, libevent 2.0.21-stable (epoll), adns: evdns2, tls: OpenSSL 1.0.1f 6 Jan 2014
2016-03-04 16:09:52.807 99616 LOG Stats: 0 req/s, in 0 b/s, out 0 b/s,query 0 us
2016-03-04 16:10:17.689 99616 NOISE new fd from accept=13
2016-03-04 16:10:17.831 99616 NOISE resync: done=0, parse=0, recv=0
2016-03-04 16:10:17.831 99616 NOISE C-0x152d780: (nodb)/(nouser)@127.0.0.1:52028 pkt='!' len=8
2016-03-04 16:10:17.831 99616 NOISE C-0x152d780: (nodb)/(nouser)@127.0.0.1:52028 C: req SSL
2016-03-04 16:10:17.831 99616 NOISE C-0x152d780: (nodb)/(nouser)@127.0.0.1:52028 P: nak
2016-03-04 16:10:17.831 99616 NOISE resync: done=8, parse=8, recv=8
2016-03-04 16:10:17.831 99616 DEBUG C-0x152d780: (nodb)/(nouser)@127.0.0.1:52028 P: got connection: 127.0.0.1:52028 -> 127.0.0.1:6432
2016-03-04 16:10:17.831 99616 NOISE safe_accept(10) = Resource temporarily unavailable
2016-03-04 16:10:17.831 99616 NOISE resync: done=0, parse=0, recv=0
2016-03-04 16:10:17.831 99616 NOISE C-0x152d780: (nodb)/(nouser)@127.0.0.1:52028 pkt='!' len=84
2016-03-04 16:10:17.831 99616 DEBUG C-0x152d780: (nodb)/(nouser)@127.0.0.1:52028 got var: user=xyz
2016-03-04 16:10:17.831 99616 DEBUG C-0x152d780: (nodb)/(nouser)@127.0.0.1:52028 got var: database=xyz
2016-03-04 16:10:17.831 99616 DEBUG C-0x152d780: (nodb)/(nouser)@127.0.0.1:52028 using application_name: psql
2016-03-04 16:10:17.831 99616 DEBUG C-0x152d780: (nodb)/(nouser)@127.0.0.1:52028 got var: client_encoding=UTF8
2016-03-04 16:10:17.831 99616 DEBUG C-0x152d780: xyz/(nouser)@127.0.0.1:52028 pause_client
2016-03-04 16:10:17.831 99616 NOISE S-0x1532430: xyz/postgres@(bad-af):0 inet socket: 127.0.0.1
2016-03-04 16:10:17.831 99616 DEBUG S-0x1532430: xyz/postgres@127.0.0.1:5432 launching new connection to server
2016-03-04 16:10:17.831 99616 DEBUG S-0x1532430: xyz/postgres@127.0.0.1:5432 S: connect ok
2016-03-04 16:10:17.831 99616 NOISE S-0x1532430: xyz/postgres@127.0.0.1:5432 P: startup
2016-03-04 16:10:17.831 99616 DEBUG pktbuf_dynamic(512): 0x152a6c0
2016-03-04 16:10:17.831 99616 DEBUG launch_new_connection: already progress
2016-03-04 16:10:17.833 99616 NOISE resync: done=0, parse=0, recv=0
2016-03-04 16:10:17.833 99616 NOISE S-0x1532430: xyz/postgres@127.0.0.1:5432 S: pkt 'R', len=13
2016-03-04 16:10:17.833 99616 DEBUG S-0x1532430: xyz/postgres@127.0.0.1:5432 calling login_answer
2016-03-04 16:10:17.833 99616 DEBUG S-0x1532430: xyz/postgres@127.0.0.1:5432 S: req md5-crypted psw
2016-03-04 16:10:17.833 99616 DEBUG S-0x1532430: xyz/postgres@127.0.0.1:5432 P: send md5 password
2016-03-04 16:10:17.833 99616 NOISE resync: done=13, parse=13, recv=13
2016-03-04 16:10:17.833 99616 DEBUG launch_new_connection: already progress
2016-03-04 16:10:17.839 99616 NOISE resync: done=0, parse=0, recv=0
2016-03-04 16:10:17.839 99616 NOISE S-0x1532430: xyz/postgres@127.0.0.1:5432 S: pkt 'R', len=9
2016-03-04 16:10:17.839 99616 DEBUG S-0x1532430: xyz/postgres@127.0.0.1:5432 calling login_answer
2016-03-04 16:10:17.839 99616 DEBUG S-0x1532430: xyz/postgres@127.0.0.1:5432 S: auth ok
2016-03-04 16:10:17.839 99616 NOISE S-0x1532430: xyz/postgres@127.0.0.1:5432 S: pkt 'S', len=23
2016-03-04 16:10:17.839 99616 DEBUG S-0x1532430: xyz/postgres@127.0.0.1:5432 S: param: application_name =
2016-03-04 16:10:17.839 99616 DEBUG pktbuf_dynamic(128): 0x152acb0
2016-03-04 16:10:17.839 99616 NOISE S-0x1532430: xyz/postgres@127.0.0.1:5432 S: pkt 'S', len=31
2016-03-04 16:10:17.839 99616 DEBUG S-0x1532430: xyz/postgres@127.0.0.1:5432 S: param: client_encoding = SQL_ASCII
2016-03-04 16:10:17.839 99616 NOISE S-0x1532430: xyz/postgres@127.0.0.1:5432 S: pkt 'S', len=24
2016-03-04 16:10:17.839 99616 DEBUG S-0x1532430: xyz/postgres@127.0.0.1:5432 S: param: DateStyle = ISO, MDY
2016-03-04 16:10:17.839 99616 NOISE S-0x1532430: xyz/postgres@127.0.0.1:5432 S: pkt 'S', len=26
2016-03-04 16:10:17.839 99616 DEBUG S-0x1532430: xyz/postgres@127.0.0.1:5432 S: param: integer_datetimes = on
2016-03-04 16:10:17.839 99616 NOISE S-0x1532430: xyz/postgres@127.0.0.1:5432 S: pkt 'S', len=28
2016-03-04 16:10:17.839 99616 DEBUG S-0x1532430: xyz/postgres@127.0.0.1:5432 S: param: IntervalStyle = postgres
2016-03-04 16:10:17.839 99616 NOISE S-0x1532430: xyz/postgres@127.0.0.1:5432 S: pkt 'S', len=21
2016-03-04 16:10:17.839 99616 DEBUG S-0x1532430: xyz/postgres@127.0.0.1:5432 S: param: is_superuser = on
2016-03-04 16:10:17.839 99616 NOISE S-0x1532430: xyz/postgres@127.0.0.1:5432 S: pkt 'S', len=31
2016-03-04 16:10:17.839 99616 DEBUG S-0x1532430: xyz/postgres@127.0.0.1:5432 S: param: server_encoding = SQL_ASCII
2016-03-04 16:10:17.839 99616 NOISE S-0x1532430: xyz/postgres@127.0.0.1:5432 S: pkt 'S', len=27
2016-03-04 16:10:17.839 99616 DEBUG S-0x1532430: xyz/postgres@127.0.0.1:5432 S: param: server_version = 9.0.22
2016-03-04 16:10:17.839 99616 DEBUG make_room(0x152acb0, 15): realloc newlen=256
2016-03-04 16:10:17.839 99616 NOISE S-0x1532430: xyz/postgres@127.0.0.1:5432 S: pkt 'S', len=36
2016-03-04 16:10:17.839 99616 DEBUG S-0x1532430: xyz/postgres@127.0.0.1:5432 S: param: session_authorization = postgres
2016-03-04 16:10:17.839 99616 NOISE S-0x1532430: xyz/postgres@127.0.0.1:5432 S: pkt 'S', len=37
2016-03-04 16:10:17.839 99616 DEBUG S-0x1532430: xyz/postgres@127.0.0.1:5432 S: param: standard_conforming_strings = off
2016-03-04 16:10:17.839 99616 NOISE S-0x1532430: xyz/postgres@127.0.0.1:5432 S: pkt 'S', len=24
2016-03-04 16:10:17.839 99616 DEBUG S-0x1532430: xyz/postgres@127.0.0.1:5432 S: param: TimeZone = localtime
2016-03-04 16:10:17.839 99616 NOISE S-0x1532430: xyz/postgres@127.0.0.1:5432 S: pkt 'K', len=13
2016-03-04 16:10:17.839 99616 NOISE S-0x1532430: xyz/postgres@127.0.0.1:5432 S: pkt 'Z', len=6
2016-03-04 16:10:17.839 99616 DEBUG S-0x1532430: xyz/postgres@127.0.0.1:5432 server login ok, start accepting queries
2016-03-04 16:10:17.839 99616 NOISE S-0x1532430: xyz/postgres@127.0.0.1:5432 release_server: new state=10
2016-03-04 16:10:17.839 99616 DEBUG C-0x152d780: xyz/(nouser)@127.0.0.1:52028 activate_client
2016-03-04 16:10:17.839 99616 NOISE resync: done=0, parse=0, recv=84
2016-03-04 16:10:17.839 99616 NOISE safe_recv(13, 524204) = Resource temporarily unavailable
2016-03-04 16:10:17.839 99616 NOISE C-0x152d780: xyz/(nouser)@127.0.0.1:52028 pkt='!' len=84
2016-03-04 16:10:17.839 99616 DEBUG C-0x152d780: xyz/(nouser)@127.0.0.1:52028 got var: user=xyz
2016-03-04 16:10:17.839 99616 DEBUG C-0x152d780: xyz/(nouser)@127.0.0.1:52028 got var: database=xyz
2016-03-04 16:10:17.839 99616 DEBUG C-0x152d780: xyz/(nouser)@127.0.0.1:52028 using application_name: psql
2016-03-04 16:10:17.839 99616 DEBUG C-0x152d780: xyz/(nouser)@127.0.0.1:52028 got var: client_encoding=UTF8
2016-03-04 16:10:17.839 99616 DEBUG S-0x1532430: xyz/postgres@127.0.0.1:5432 varcache_apply: SET client_encoding='UTF8';SET application_name='psql';
2016-03-04 16:10:17.839 99616 NOISE resync: done=336, parse=336, recv=336
2016-03-04 16:10:17.839 99616 NOISE resync: done=0, parse=0, recv=0
2016-03-04 16:10:17.839 99616 NOISE S-0x1532430: xyz/postgres@127.0.0.1:5432 S: pkt 'S', len=26
2016-03-04 16:10:17.840 99616 DEBUG S-0x1532430: xyz/postgres@127.0.0.1:5432 S: param: client_encoding = UTF8
2016-03-04 16:10:17.840 99616 DEBUG C-0x152d780: xyz/(nouser)@127.0.0.1:52028 setting client var: client_encoding='UTF8'
2016-03-04 16:10:17.840 99616 NOISE S-0x1532430: xyz/postgres@127.0.0.1:5432 S: pkt 'C', len=9
2016-03-04 16:10:17.840 99616 NOISE S-0x1532430: xyz/postgres@127.0.0.1:5432 S: pkt 'S', len=27
2016-03-04 16:10:17.840 99616 DEBUG S-0x1532430: xyz/postgres@127.0.0.1:5432 S: param: application_name = psql
2016-03-04 16:10:17.840 99616 DEBUG C-0x152d780: xyz/(nouser)@127.0.0.1:52028 setting client var: application_name='psql'
2016-03-04 16:10:17.840 99616 NOISE S-0x1532430: xyz/postgres@127.0.0.1:5432 S: pkt 'C', len=9
2016-03-04 16:10:17.840 99616 NOISE S-0x1532430: xyz/postgres@127.0.0.1:5432 S: pkt 'Z', len=6
2016-03-04 16:10:17.840 99616 NOISE resync: done=77, parse=77, recv=77
2016-03-04 16:10:17.840 99616 NOISE resync: done=0, parse=0, recv=84
2016-03-04 16:10:17.840 99616 NOISE safe_recv(13, 524204) = Resource temporarily unavailable
2016-03-04 16:10:17.840 99616 NOISE C-0x152d780: xyz/(nouser)@127.0.0.1:52028 pkt='!' len=84
2016-03-04 16:10:17.840 99616 DEBUG C-0x152d780: xyz/(nouser)@127.0.0.1:52028 got var: user=xyz
2016-03-04 16:10:17.840 99616 DEBUG C-0x152d780: xyz/(nouser)@127.0.0.1:52028 got var: database=xyz
2016-03-04 16:10:17.840 99616 DEBUG C-0x152d780: xyz/(nouser)@127.0.0.1:52028 using application_name: psql
2016-03-04 16:10:17.840 99616 DEBUG C-0x152d780: xyz/(nouser)@127.0.0.1:52028 got var: client_encoding=UTF8
2016-03-04 16:10:17.840 99616 NOISE C-0x152d780: xyz/(nouser)@127.0.0.1:52028 Doing auth_conn query
2016-03-04 16:10:17.840 99616 DEBUG pktbuf_dynamic(512): 0x1537340
2016-03-04 16:10:17.840 99616 DEBUG pktbuf_free(0x1537340)
2016-03-04 16:10:17.892 99616 NOISE resync: done=0, parse=0, recv=0
2016-03-04 16:10:17.892 99616 NOISE S-0x1532430: xyz/postgres@127.0.0.1:5432 S: pkt '1', len=5
2016-03-04 16:10:17.892 99616 NOISE S-0x1532430: xyz/postgres@127.0.0.1:5432 S: pkt '2', len=5
2016-03-04 16:10:17.892 99616 NOISE S-0x1532430: xyz/postgres@127.0.0.1:5432 S: pkt 'T', len=58
2016-03-04 16:10:17.892 99616 NOISE S-0x1532430: xyz/postgres@127.0.0.1:5432 S: pkt 'D', len=58
2016-03-04 16:10:17.892 99616 NOISE S-0x1532430: xyz/postgres@127.0.0.1:5432 S: pkt 'C', len=14
2016-03-04 16:10:17.892 99616 NOISE S-0x1532430: xyz/postgres@127.0.0.1:5432 S: pkt 'Z', len=6
2016-03-04 16:10:17.892 99616 DEBUG C-0x152d780: xyz/xyz@127.0.0.1:52028 unexpected ReadyForQuery - expect_rfq_count=0
2016-03-04 16:10:17.892 99616 NOISE C-0x152d780: xyz/xyz@127.0.0.1:52028 auth query complete
2016-03-04 16:10:17.892 99616 NOISE resync: done=0, parse=0, recv=84
2016-03-04 16:10:17.892 99616 NOISE safe_recv(13, 524204) = Resource temporarily unavailable
2016-03-04 16:10:17.892 99616 NOISE C-0x152d780: xyz/xyz@127.0.0.1:52028 pkt='!' len=84
2016-03-04 16:10:17.892 99616 WARNING C-0x152d780: xyz/xyz@127.0.0.1:52028 Pooler Error: login rejected

Any ideas why?

ps. When setting auth_type to md5, everything works perfectly well.

Metadata

Metadata

Assignees

No one assigned

    Labels

    No labels
    No labels

    Type

    No type

    Projects

    No projects

    Milestone

    No milestone

    Relationships

    None yet

    Development

    No branches or pull requests

    Issue actions