View Issue Details

Jump to NotesJump to History
IDProjectCategoryView StatusDate SubmittedLast Update
0000464Pgpool-IIBugpublic2019-02-13 01:582019-03-11 10:56
Reportercaudatus Assigned Topengbo  
PrioritynormalSeverityminorReproducibilityalways
Status resolvedResolutionopen 
PlatformLinuxOSCentOSOS Version7
Product Version4.0.2 
Summary0000464: pool_passwd with md5 / DETAIL: username "pgpcheck" has invalid password type: 2
Descriptionroot@pgproxy4-dbtest-plus-dp1:/etc/pgpool-II# cat BUG_DESCRIPTION
###################################################################
md5 pool passwd auth with an earlier 3.*.* version of pgpool does work,
but with 4.0.2 it cannot work.
###################################################################

1. if pool_passwd contains cleartext pass (pgpcheck:TEXTxxx), authentication works,
2. even if I configed cleartext pass in pgpool.conf, it also works,

3. BUT: if pool_passwd was generated by pg_md5 command (meanwhile the generated local md5 hash is the same as postgresql master pg_shadow record),
authentication goes wrong and gives error message:
2019-02-12T15:28:56.000000+00:00 pgproxy4-dbtest-plus-dp1 pgpool[18038]: [221-1] 2019-02-12 15:28:56: pid 18038: DEBUG: could not get the password for user:pgpcheck
2019-02-12T15:28:56.000000+00:00 pgproxy4-dbtest-plus-dp1 pgpool[18038]: [221-2] 2019-02-12 15:28:56: pid 18038: DETAIL: username "pgpcheck" has invalid password type: 2



full log environment nearby:
...
2019-02-12T15:28:56.000000+00:00 pgproxy4-dbtest-plus-dp1 pgpool[18036]: [219-2] 2019-02-12 15:28:56: pid 18036: LOCATION: pcp_child.c:148
2019-02-12T15:28:56.000000+00:00 pgproxy4-dbtest-plus-dp1 pgpool[18037]: [220-1] 2019-02-12 15:28:56: pid 18037: DEBUG: initializing backend status
2019-02-12T15:28:56.000000+00:00 pgproxy4-dbtest-plus-dp1 pgpool[18038]: [220-1] 2019-02-12 15:28:56: pid 18038: DEBUG: initializing backend status
2019-02-12T15:28:56.000000+00:00 pgproxy4-dbtest-plus-dp1 pgpool[18037]: [220-2] 2019-02-12 15:28:56: pid 18037: LOCATION: child.c:1759
2019-02-12T15:28:56.000000+00:00 pgproxy4-dbtest-plus-dp1 pgpool[18038]: [220-2] 2019-02-12 15:28:56: pid 18038: LOCATION: child.c:1759
2019-02-12T15:28:56.000000+00:00 pgproxy4-dbtest-plus-dp1 pgpool[18031]: [219-1] 2019-02-12 15:28:56: pid 18031: LOG: pgpool-II successfully started. version 4.0.2 (torokiboshi)
2019-02-12T15:28:56.000000+00:00 pgproxy4-dbtest-plus-dp1 pgpool[18031]: [219-2] 2019-02-12 15:28:56: pid 18031: LOCATION: pgpool_main.c:464
2019-02-12T15:28:56.000000+00:00 pgproxy4-dbtest-plus-dp1 pgpool[18031]: [220-1] 2019-02-12 15:28:56: pid 18031: LOG: node status[0]: 1
2019-02-12T15:28:56.000000+00:00 pgproxy4-dbtest-plus-dp1 pgpool[18031]: [220-2] 2019-02-12 15:28:56: pid 18031: LOCATION: pgpool_main.c:475
2019-02-12T15:28:56.000000+00:00 pgproxy4-dbtest-plus-dp1 pgpool[18038]: [221-1] 2019-02-12 15:28:56: pid 18038: DEBUG: could not get the password for user:pgpcheck
2019-02-12T15:28:56.000000+00:00 pgproxy4-dbtest-plus-dp1 pgpool[18038]: [221-2] 2019-02-12 15:28:56: pid 18038: DETAIL: username "pgpcheck" has invalid password type: 2
2019-02-12T15:28:56.000000+00:00 pgproxy4-dbtest-plus-dp1 pgpool[18031]: [221-1] 2019-02-12 15:28:56: pid 18031: LOG: node status[1]: 0
2019-02-12T15:28:56.000000+00:00 pgproxy4-dbtest-plus-dp1 pgpool[18038]: [221-3] 2019-02-12 15:28:56: pid 18038: LOCATION: pool_passwd.c:525
2019-02-12T15:28:56.000000+00:00 pgproxy4-dbtest-plus-dp1 pgpool[18031]: [221-2] 2019-02-12 15:28:56: pid 18031: LOCATION: pgpool_main.c:475
2019-02-12T15:28:56.000000+00:00 pgproxy4-dbtest-plus-dp1 pgpool[18038]: [222-1] 2019-02-12 15:28:56: pid 18038: DEBUG: attempting to negotiate a secure connection
2019-02-12T15:28:56.000000+00:00 pgproxy4-dbtest-plus-dp1 pgpool[18038]: [222-2] 2019-02-12 15:28:56: pid 18038: DETAIL: sending client->server SSL request
2019-02-12T15:28:56.000000+00:00 pgproxy4-dbtest-plus-dp1 pgpool[18038]: [222-3] 2019-02-12 15:28:56: pid 18038: LOCATION: pool_ssl.c:98
...


postgresql master pg_hba.conf:
hostssl all all 172.18.0.0/24 md5
hostssl replication postgres 172.18.0.0/24 trust

postgresql master log:
2019-02-12 15:28:59.315 UTC,"pgpcheck","postgres",6152,"pgproxy-dbtest.docker1:52340",5c62e63b.1808,2,"authentication",2019-02-12 15:28:59 UTC,2/2351,0,FATAL,28P01,"password authentication failed for user ""pgpcheck""","Connection matched pg_hba.conf line 95: ""hostssl all all 172.18.0.0/24 md5""",,,,,,,,""
2019-02-12 15:29:00.321 UTC,,,6153,"pgproxy-dbtest.docker1:52342",5c62e63c.1809,1,"",2019-02-12 15:29:00 UTC,,0,LOG,00000,"connection received: host=pgproxy-dbtest.docker1 port=52342",,,,,,,,,""
2019-02-12 15:29:00.336 UTC,"pgpcheck","postgres",6153,"pgproxy-dbtest.docker1:52342",5c62e63c.1809,2,"authentication",2019-02-12 15:29:00 UTC,2/2352,0,FATAL,28P01,"password authentication failed for user ""pgpcheck""","Connection matched pg_hba.conf line 95: ""hostssl all all 172.18.0.0/24 md5""",,,,,,,,""
2019-02-12 15:29:01.341 UTC,,,6154,"pgproxy-dbtest.docker1:52344",5c62e63d.180a,1,"",2019-02-12 15:29:01 UTC,,0,LOG,00000,"connection received: host=pgproxy-dbtest.docker1 port=52344",,,,,,,,,""
2019-02-12 15:29:01.356 UTC,"pgpcheck","postgres",6154,"pgproxy-dbtest.docker1:52344",5c62e63d.180a,2,"authentication",2019-02-12 15:29:01 UTC,2/2353,0,FATAL,28P01,"password authentication failed for user ""pgpcheck""","Connection matched pg_hba.conf line 95: ""hostssl all all 172.18.0.0/24 md5""",,,,,,,,""
2019-02-12 15:29:03.923 UTC,,,6156,"postgresql-db2.docker1:54530",5c62e63f.180c,1,"",2019-02-12 15:29:03 UTC,,0,LOG,00000,"connection received: host=postgresql-db2.docker1 port=54530",,,,,,,,,""


I've attached strace of pgpool (filecalled: trace), according part of it is:

18031 fstat(4, {st_mode=S_IFREG|0644, st_size=663, ...}) = 0
18031 mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f3c26849000
18031 read(4, "root:x:0:0:root:/root:/bin/bash\nbin:x:1:1:bin:/bin:/sbin/nologin\ndaemon:x:2:2:daemon:/sbin:/sbin/nologin\nadm:x:3:4:adm:/var/adm:/sbin/nologin\nlp:x:4:7:lp:/var/spool/lpd:/sbin/nologin\nsync:x:5:0:sync:/sbin:/bin/sync\nshutdown:x:6:0:shutdown:/sbin:/sbin/shutdown\nhalt:x:7:0:halt:/sbin:/sbin/halt\nmail:x:8:12:mail:/var/spool/mail:/sbin/nologin\noperator:x:11:0:operator:/root:/sbin/nologin\ngames:x:12:100:games:/usr/games:/sbin/nologin\nftp:x:14:50:FTP User:/var/ftp:/sbin/nologin\nnobody:x:99:99:Nobody:/:/"..., 4096) = 663
18031 close(4) = 0
18031 munmap(0x7f3c26849000, 4096) = 0
18031 stat("/root/.pgpoolkey", 0x7ffd2ceb4cb0) = -1 ENOENT (No such file or directory)
18031 open("/var/run/pgpool/pgpool.pid", O_WRONLY|O_CREAT, 0600) = 4
18031 write(4, "18031\0", 6) = 6
18031 fsync(4) = 0
18031 close(4) = 0
18031 open("/etc/pgpool-II/pool_passwd", O_RDONLY) = 4
18031 semget(IPC_PRIVATE, 6, IPC_CREAT|IPC_EXCL|0600) = 655360
18031 semctl(655360, 0, SETVAL, 0x1) = 0
18031 semctl(655360, 1, SETVAL, 0x1) = 0
18031 semctl(655360, 2, SETVAL, 0x1) = 0
18031 semctl(655360, 3, SETVAL, 0x1) = 0
18031 semctl(655360, 4, SETVAL, 0x1) = 0
18031 semctl(655360, 5, SETVAL, 0x1) = 0
18031 open("/var/log/pgpool/pgpool_status", O_RDONLY) = 5
18031 fstat(5, {st_mode=S_IFREG|0644, st_size=8, ...}) = 0
18031 mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f3c26849000
--
18031 stat("/etc/localtime", <unfinished ...>
18035 sendto(3, "<135>Feb 12 15:28:56 pgpool[18035]: [180-2] 2019-02-12 15:28:56: pid 18035: LOCATION: child.c:1759", 99, MSG_NOSIGNAL, NULL, 0 <unfinished ...>
18031 <... stat resumed> {st_mode=S_IFREG|0644, st_size=118, ...}) = 0
18035 <... sendto resumed> ) = 99
18031 stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=118, ...}) = 0
18031 sendto(3, "<135>Feb 12 15:28:56 pgpool[18031]: [181-1] 2019-02-12 15:28:56: pid 18031: DEBUG: pool_flush_it: flush size: 8", 112, MSG_NOSIGNAL, NULL, 0) = 112
18035 close(4 <unfinished ...>
18031 sendto(3, "<135>Feb 12 15:28:56 pgpool[18031]: [181-2] 2019-02-12 15:28:56: pid 18031: LOCATION: pool_stream.c:633", 104, MSG_NOSIGNAL, NULL, 0 <unfinished ...>
18035 <... close resumed> ) = 0
18031 <... sendto resumed> ) = 104
18035 open("/etc/pgpool-II/pool_passwd", O_RDONLY <unfinished ...>
18031 write(10, "\0\0\0\10\4\322\26/", 8 <unfinished ...>
18035 <... open resumed> ) = 4
18035 rt_sigprocmask(SIG_BLOCK, NULL, <unfinished ...>
18031 <... write resumed> ) = 8
18035 <... rt_sigprocmask resumed> [], 8) = 0
18031 select(11, [10], NULL, [10], NULL <unfinished ...>
18035 fcntl(5, F_GETFL) = 0x802 (flags O_RDWR|O_NONBLOCK)
18035 fcntl(5, F_SETFL, O_RDWR|O_NONBLOCK) = 0
18035 fcntl(6, F_GETFL) = 0x802 (flags O_RDWR|O_NONBLOCK)
18035 fcntl(6, F_SETFL, O_RDWR|O_NONBLOCK) = 0
--
18038 <... stat resumed> {st_mode=S_IFREG|0644, st_size=118, ...}) = 0
18031 sendto(3, "<134>Feb 12 15:28:56 pgpool[18031]: [220-2] 2019-02-12 15:28:56: pid 18031: LOCATION: pgpool_main.c:475", 104, MSG_NOSIGNAL, NULL, 0 <unfinished ...>
18038 stat("/etc/localtime", <unfinished ...>
18031 <... sendto resumed> ) = 104
18038 <... stat resumed> {st_mode=S_IFREG|0644, st_size=118, ...}) = 0
18031 stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=118, ...}) = 0
18038 sendto(3, "<135>Feb 12 15:28:56 pgpool[18038]: [221-1] 2019-02-12 15:28:56: pid 18038: DEBUG: could not get the password for user:pgpcheck", 128, MSG_NOSIGNAL, NULL, 0 <unfinished ...>
18031 stat("/etc/localtime", <unfinished ...>
18038 <... sendto resumed> ) = 128
18031 <... stat resumed> {st_mode=S_IFREG|0644, st_size=118, ...}) = 0
18038 sendto(3, "<135>Feb 12 15:28:56 pgpool[18038]: [221-2] 2019-02-12 15:28:56: pid 18038: DETAIL: username \"pgpcheck\" has invalid password type: 2", 133, MSG_NOSIGNAL, NULL, 0 <unfinished ...>
18031 sendto(3, "<134>Feb 12 15:28:56 pgpool[18031]: [221-1] 2019-02-12 15:28:56: pid 18031: LOG: node status[1]: 0", 99, MSG_NOSIGNAL, NULL, 0 <unfinished ...>
18038 <... sendto resumed> ) = 133
18031 <... sendto resumed> ) = 99
18038 sendto(3, "<135>Feb 12 15:28:56 pgpool[18038]: [221-3] 2019-02-12 15:28:56: pid 18038: LOCATION: pool_passwd.c:525", 104, MSG_NOSIGNAL, NULL, 0 <unfinished ...>
18031 sendto(3, "<134>Feb 12 15:28:56 pgpool[18031]: [221-2] 2019-02-12 15:28:56: pid 18031: LOCATION: pgpool_main.c:475", 104, MSG_NOSIGNAL, NULL, 0 <unfinished ...>
18038 <... sendto resumed> ) = 104
18031 <... sendto resumed> ) = 104
18031 rt_sigprocmask(SIG_SETMASK, [], NULL, 8) = 0
18038 socket(AF_INET, SOCK_STREAM, IPPROTO_TCP <unfinished ...>
18031 select(9, [8], NULL, NULL, {3, 0} <unfinished ...>
18038 <... socket resumed> ) = 8
18038 setsockopt(8, SOL_TCP, TCP_NODELAY, [1], 4) = 0
18038 fcntl(8, F_GETFL) = 0x2 (flags O_RDWR)
18038 fcntl(8, F_SETFL, O_RDWR|O_NONBLOCK) = 0
Steps To Reproducei've attached config files and reports
checked md5 hash against postgresql master and hashes are the same in pool_passwd and in db:
root@postgresql-db1-plus-dp1|postgresql-db1:/# psql -A -t -U postgres -c 'select * from pg_catalog.pg_shadow;'
pgpcheck|41003|f|f|f|f|md5f04635afb01c7b34299796bb8d97bf7c||

it seems the failure was happened while parsing pool_passwd content (see trace file)
Tagsmd5, pgpool-II

Activities

caudatus

2019-02-13 01:58

reporter  

etc.pgpool.tgz (63,001 bytes)

pengbo

2019-02-13 12:03

developer   ~0002384

For parameters "health_check_password", "sr_check_password", "wd_lifecheck_password" and "recovery_password",
only AES encrypted password or clear text password can be used.

So you can't use md5 authentication method by "health_check_user", "sr_check_user", "wd_lifecheck_user" and "recovery_user".

See more details:
http://www.pgpool.net/docs/latest/en/html/runtime-config-health-check.html#GUC-HEALTH-CHECK-PASSWORD

caudatus

2019-03-08 02:26

reporter   ~0002426

thanks a lot!
sorry for misunderstanding!

Issue History

Date Modified Username Field Change
2019-02-13 01:58 caudatus New Issue
2019-02-13 01:58 caudatus File Added: etc.pgpool.tgz
2019-02-13 01:58 caudatus Tag Attached: pgpool-II
2019-02-13 01:58 caudatus Tag Attached: md5
2019-02-13 12:00 administrator Assigned To => pengbo
2019-02-13 12:00 administrator Status new => assigned
2019-02-13 12:03 pengbo Note Added: 0002384
2019-02-13 12:03 pengbo Status assigned => feedback
2019-03-08 02:26 caudatus Note Added: 0002426
2019-03-08 02:26 caudatus Status feedback => assigned
2019-03-11 10:56 pengbo Status assigned => resolved