You are viewing a plain text version of this content. The canonical link for it is here.
Posted to dev@apr.apache.org by Rainer Jung <ra...@kippdata.de> on 2013/02/20 23:56:37 UTC
Re: [VOTE] Release Apache httpd 2.4.4 as GA
On 20.02.2013 22:33, Noel Butler wrote:
> On Wed, 2013-02-20 at 09:07 +0100, Rainer Jung wrote:
>> 2) Keep original validation code but ad some debug output to STDERR:
>>
>> http://people.apache.org/~rjung/patches/apr-util-password_validate-debug.patch <http://people.apache.org/%7Erjung/patches/apr-util-password_validate-debug.patch>
>>
> Fails
>
> [Thu Feb 21 07:18:27.549401 2013] [auth_basic:trace1] [pid 31295:tid
> 3012647792] mod_auth_basic.c(246): [client fd1d:c01d:1ce::145:58603]
> Checking password for user '' using provider 'dbd', result: 3
>
> [Thu Feb 21 07:18:27.549593 2013] [auth_basic:error] [pid 31295:tid
> 3012647792] [client fd1d:c01d:1ce::145:58603] AH01618: user not found: /
>
> [Thu Feb 21 07:18:29.308367 2013] [authn_dbd:trace2] [pid 31295:tid
> 3004259184] mod_authn_dbd.c(178): [client fd1d:c01d:1ce::145:58603] Got
> hashed password '$6$xxxxxxxxx' for user 'noel'
>
> [Thu Feb 21 07:18:29.308437 2013] [authn_dbd:debug] [pid 31295:tid
> 3004259184] mod_authn_dbd.c(199): (70024)passwords do not match: [client
> fd1d:c01d:1ce::145:58603] Call to apr_password_validate for user 'noel'
> and hashed password '$6$xxxx' validate returned an error
>
> [Thu Feb 21 07:18:29.308471 2013] [auth_basic:trace1] [pid 31295:tid
> 3004259184] mod_auth_basic.c(246): [client fd1d:c01d:1ce::145:58603]
> Checking password for user 'noel' using provider 'dbd', result: 0
>
> [Thu Feb 21 07:18:29.308505 2013] [auth_basic:error] [pid 31295:tid
> 3004259184] [client fd1d:c01d:1ce::145:58603] AH01617: user noel:
> authentication failure for "/": Password Mismatch
That's strange, the additional stderr output
"crypt_r returned NULL"
or
"crypt_r returned '%s'"
is not shown here.
As an alternative one could use strace to check the call to crypt_r and
the return value.
Rainer
Re: [VOTE] Release Apache httpd 2.4.4 as GA
Posted by Noel Butler <no...@ausics.net>.
On Sat, 2013-02-23 at 13:29 +0100, Rainer Jung wrote:
> Concerning the apr_password_validate() problem in APU 1.5.1 and related
> httpd release testing failures:
>
> The bug was fixed in
>
> http://svn.apache.org/viewvc?view=revision&revision=1449309
>
> Don't know how I could stare so long at the code without seeing the
> obvious bug. Thanks to the reporter of PR 54603 for the correct patch.
>
> Regards,
>
> Rainer
Confirmed fixed in 2.4.4 (and 2.2.24) thanks for your time Rainer, much
appreciated.
Re: [VOTE] Release Apache httpd 2.4.4 as GA
Posted by Noel Butler <no...@ausics.net>.
On Sat, 2013-02-23 at 13:29 +0100, Rainer Jung wrote:
> Concerning the apr_password_validate() problem in APU 1.5.1 and related
> httpd release testing failures:
>
> The bug was fixed in
>
> http://svn.apache.org/viewvc?view=revision&revision=1449309
>
> Don't know how I could stare so long at the code without seeing the
> obvious bug. Thanks to the reporter of PR 54603 for the correct patch.
>
> Regards,
>
> Rainer
Confirmed fixed in 2.4.4 (and 2.2.24) thanks for your time Rainer, much
appreciated.
Re: [VOTE] Release Apache httpd 2.4.4 as GA
Posted by Rainer Jung <ra...@kippdata.de>.
Concerning the apr_password_validate() problem in APU 1.5.1 and related
httpd release testing failures:
The bug was fixed in
http://svn.apache.org/viewvc?view=revision&revision=1449309
Don't know how I could stare so long at the code without seeing the
obvious bug. Thanks to the reporter of PR 54603 for the correct patch.
Regards,
Rainer
Re: [VOTE] Release Apache httpd 2.4.4 as GA
Posted by Rainer Jung <ra...@kippdata.de>.
Concerning the apr_password_validate() problem in APU 1.5.1 and related
httpd release testing failures:
The bug was fixed in
http://svn.apache.org/viewvc?view=revision&revision=1449309
Don't know how I could stare so long at the code without seeing the
obvious bug. Thanks to the reporter of PR 54603 for the correct patch.
Regards,
Rainer
Re: [VOTE] Release Apache httpd 2.4.4 as GA
Posted by Noel Butler <no...@ausics.net>.
On Thu, 2013-02-21 at 10:24 +1000, Noel Butler wrote:
> On Wed, 2013-02-20 at 23:56 +0100, Rainer Jung wrote:
>
>
> >
> > That's strange, the additional stderr output
> >
> > "crypt_r returned NULL"
> >
> > or
> >
> > "crypt_r returned '%s'"
> >
> > is not shown here.
> >
>
>
> Indeed, I'm running :
> LogLevel debug auth_basic:trace8 authn_dbd:trace8
>
> Briefly ran trace8 globally, but only briefly for obvious reasons, my
> eyes were starting to bleed :)
>
>
> > As an alternative one could use strace to check the call to crypt_r and
>
>
> strace only shows...
>
> 29311 gettimeofday({1361405772, 894610}, NULL) = 0
> 29311 poll([{fd=17, events=POLLIN|POLLPRI}], 1, 0) = 0 (Timeout)
> 29311 write(17, "*\0\0\0\26SELECT Password FROM users WHERE User
> = ?"..., 46) = 46
> 29311 read(17, "\f\0\0\1\0\1\0\0\0\1\0\1\0\0\0\0\27\0\0\2\3def\0\0\0
> \1?\0\f?\0\0\0\0\0\375\200\0\0\0\0\5\0\0\3\376\0\0\2\0007\0\0\4\3def
> \7members\5users\5users\10Password\10Password\f\10\0\0\1\0\0\375\201
> \20\0\0\0\5\0\0\5\376\0\0\2\0"..., 16384) = 120
> 29311 poll([{fd=17, events=POLLIN|POLLPRI}], 1, 0) = 0 (Timeout)
> 29311 poll([{fd=17, events=POLLIN|POLLPRI}], 1, 0) = 0 (Timeout)
> 29311 write(17, "\23\0\0\0\27\1\0\0\0\0\1\0\0\0\0\1\375\0\4noel"...,
> 23) = 23
> 29311 read(17, "\1\0\0\1\0017\0\0\2\3def\7members\5users\5users
> \10Password\10Password\f\10\0\0\1\0\0\375\201\20\0\0\0\5\0\0\3\376\0\0
> \2\0m\0\0\4\0\0j$6$xxxxxxxxxxxx\5\0\0\5\376\0\0\2\0"..., 16384) = 195
> 29311 gettimeofday({1361405772, 895721}, NULL) = 0
> 29311 write(8, "[Thu Feb 21 10:16:12.895721 2013] [authn_dbd:trace2]
> [pid 29307:tid 3046349680] mod_authn_dbd.c(178): [client
> fd1d:c01d:1ce::145:59592] Got hashed password '$6$xxxxxxxxxxxxx' for
> user 'noel'\n"..., 281) = 281
> 29311 gettimeofday({1361405772, 895975}, NULL) = 0
> 29311 write(8, "[Thu Feb 21 10:16:12.895975 2013] [authn_dbd:debug]
> [pid 29307:tid 3046349680] mod_authn_dbd.c(199): (70024)passwords do
> not match: [client fd1d:c01d:1ce::145:59592] Call to
> apr_password_validate for user 'noel' and hashed password '$6
> $xxxxxxxxxxx"..., 368) = 368
> 29311 gettimeofday({1361405772, 896212}, NULL) = 0
> 29311 write(8, "[Thu Feb 21 10:16:12.896212 2013] [auth_basic:trace1]
> [pid 29307:tid 3046349680] mod_auth_basic.c(246): [client
> fd1d:c01d:1ce::145:59592] Checking password for user 'noel' using
> provider 'dbd', result: 0\n"..., 204) = 204
> 29311 gettimeofday({1361405772, 896399}, NULL) = 0
> 29311 write(8, "[Thu Feb 21 10:16:12.896399 2013] [auth_basic:error]
> [pid 29307:tid 3046349680] [client fd1d:c01d:1ce::145:59592] AH01617:
> user noel: authentication failure for \"/\": Password Mismatch\n"...,
> 184) = 184
> 29311 gettimeofday({1361405772, 896750}, NULL) = 0
> 29311 read(16, 0x8537248, 8000) = -1 EAGAIN (Resource
> temporarily unavailable)
> 29311 gettimeofday({1361405772, 896880}, NULL) = 0
> 29311 gettimeofday({1361405772, 896933}, NULL) = 0
>
>
I don't know if it offers any insight, but running the same strace
command tonight on 2.4.3 with apru1.4.1
prior to, and what I do not see in apru 1.5.1 output (as per above), but
do see in 2.4.3 and apru1.4.1, is talking to mysql
8526 close(17) = 0
8526 socket(PF_INET, SOCK_STREAM, IPPROTO_TCP) = 17
8526 connect(17, {sa_family=AF_INET, sin_port=htons(3306),
sin_addr=inet_addr("guilty.IP.removed")}, 16) = 0
8526 fcntl64(17, F_SETFL, O_RDONLY) = 0
8526 fcntl64(17, F_GETFL) = 0x2 (flags O_RDWR)
8526 setsockopt(17, SOL_SOCKET, SO_RCVTIMEO, "\2003\341\1\0\0\0\0"...,
8) = 0
8526 setsockopt(17, SOL_SOCKET, SO_SNDTIMEO, "\2003\341\1\0\0\0\0"...,
8) = 0
8526 setsockopt(17, SOL_IP, IP_TOS, [8], 4) = 0
8526 setsockopt(17, SOL_TCP, TCP_NODELAY, [1], 4) = 0
8526 setsockopt(17, SOL_SOCKET, SO_KEEPALIVE, [1], 4) = 0
8526 read(17, "N\0\0\0\n5.5.30-log\0!\v\0\0x'SNlXQl\0\377\367\10\2\0\17
\200\25\0\0\0\0\0\0\0\0\0\0M|J:$B
\0mysql_native_password\0"..., 16384) = 82
8526 brk(0x856e000) = 0x856e000
8526 stat64("/usr/share/charsets/Index.xml", {st_dev=makedev(8, 1),
st_ino=1359901, st_mode=S_IFREG|0644, st_n
link=1, st_uid=0, st_gid=0, st_blksize=4096, st_blocks=40,
st_size=18312, st_atime=2013/02/22-11:56:39, st_mtim
e=2013/01/16-17:35:18, st_ctime=2013/02/06-11:28:28}) = 0
8526 open("/usr/share/charsets/Index.xml", O_RDONLY|O_LARGEFILE) = 18
8526 read(18, "<?xml version='1.0' encoding=\"utf-8\"?>\n\n<charsets
max-id=\"99\">\n\n<copyright>\n Copyright (c) 2003, 2012, Oracle
and/or its affiliates. All rights reserved.\n\n This program is free
software; you can redistribute it and/or modify\n it under the terms of
the GNU General Public License as published by\n "..., 18312) = 18312
8526 close(18) = 0
8526 futex(0xb73c7c80, FUTEX_WAKE_PRIVATE, 2147483647) = 0
8526 write(17, "Z\0\0\1\r\242\16\0\0\0\0@\10\0\0\0\0\0\0\0\0\0\0\0\0\0
\0\0\0\0\0\0\0\0\0\0DBASEUSERRME\0\24d\234ssg\272=\2i(\t\to\336\351\332
\17\314\261fmembers\0mysql_native_password\0"..., 94) = 94
8526 read(17, "\7\0\0\2\0\0\0\2\0\0\0"..., 16384) = 11
8526 poll([{fd=17, events=POLLIN|POLLPRI}], 1, 0) = 0 (Timeout)
8526 write(17, "\1\0\0\0\16"..., 5) = 5
8526 read(17, "\7\0\0\1\0\0\0\2\0\0\0"..., 16384) = 11
8526 gettimeofday({1361528535, 599942}, NULL) = 0
8526 poll([{fd=17, events=POLLIN|POLLPRI}], 1, 0) = 0 (Timeout)
8526 write(17, "*\0\0\0\26SELECT Password FROM users WHERE User
= ?"..., 46) = 46
its almost like 1.5.1 is not talking passing off to the system crypt,
but I'm only guessing. I did -Nau diff on 1.4.1 to 1.5.1 and seems a
mammoth amount of apr_password changes, so I wouldn't have the first
clue where to start looking further, hope that helps.
Re: [VOTE] Release Apache httpd 2.4.4 as GA
Posted by Noel Butler <no...@ausics.net>.
On Wed, 2013-02-20 at 23:56 +0100, Rainer Jung wrote:
>
> That's strange, the additional stderr output
>
> "crypt_r returned NULL"
>
> or
>
> "crypt_r returned '%s'"
>
> is not shown here.
>
Indeed, I'm running :
LogLevel debug auth_basic:trace8 authn_dbd:trace8
Briefly ran trace8 globally, but only briefly for obvious reasons, my
eyes were starting to bleed :)
> As an alternative one could use strace to check the call to crypt_r and
strace only shows...
29311 gettimeofday({1361405772, 894610}, NULL) = 0
29311 poll([{fd=17, events=POLLIN|POLLPRI}], 1, 0) = 0 (Timeout)
29311 write(17, "*\0\0\0\26SELECT Password FROM users WHERE User
= ?"..., 46) = 46
29311 read(17, "\f\0\0\1\0\1\0\0\0\1\0\1\0\0\0\0\27\0\0\2\3def\0\0\0
\1?\0\f?\0\0\0\0\0\375\200\0\0\0\0\5\0\0\3\376\0\0\2\0007\0\0\4\3def
\7members\5users\5users\10Password\10Password\f\10\0\0\1\0\0\375\201\20
\0\0\0\5\0\0\5\376\0\0\2\0"..., 16384) = 120
29311 poll([{fd=17, events=POLLIN|POLLPRI}], 1, 0) = 0 (Timeout)
29311 poll([{fd=17, events=POLLIN|POLLPRI}], 1, 0) = 0 (Timeout)
29311 write(17, "\23\0\0\0\27\1\0\0\0\0\1\0\0\0\0\1\375\0\4noel"..., 23)
= 23
29311 read(17, "\1\0\0\1\0017\0\0\2\3def\7members\5users\5users
\10Password\10Password\f\10\0\0\1\0\0\375\201\20\0\0\0\5\0\0\3\376\0\0\2
\0m\0\0\4\0\0j$6$xxxxxxxxxxxx\5\0\0\5\376\0\0\2\0"..., 16384) = 195
29311 gettimeofday({1361405772, 895721}, NULL) = 0
29311 write(8, "[Thu Feb 21 10:16:12.895721 2013] [authn_dbd:trace2]
[pid 29307:tid 3046349680] mod_authn_dbd.c(178): [client
fd1d:c01d:1ce::145:59592] Got hashed password '$6$xxxxxxxxxxxxx' for
user 'noel'\n"..., 281) = 281
29311 gettimeofday({1361405772, 895975}, NULL) = 0
29311 write(8, "[Thu Feb 21 10:16:12.895975 2013] [authn_dbd:debug] [pid
29307:tid 3046349680] mod_authn_dbd.c(199): (70024)passwords do not
match: [client fd1d:c01d:1ce::145:59592] Call to apr_password_validate
for user 'noel' and hashed password '$6$xxxxxxxxxxx"..., 368) = 368
29311 gettimeofday({1361405772, 896212}, NULL) = 0
29311 write(8, "[Thu Feb 21 10:16:12.896212 2013] [auth_basic:trace1]
[pid 29307:tid 3046349680] mod_auth_basic.c(246): [client
fd1d:c01d:1ce::145:59592] Checking password for user 'noel' using
provider 'dbd', result: 0\n"..., 204) = 204
29311 gettimeofday({1361405772, 896399}, NULL) = 0
29311 write(8, "[Thu Feb 21 10:16:12.896399 2013] [auth_basic:error]
[pid 29307:tid 3046349680] [client fd1d:c01d:1ce::145:59592] AH01617:
user noel: authentication failure for \"/\": Password Mismatch\n"...,
184) = 184
29311 gettimeofday({1361405772, 896750}, NULL) = 0
29311 read(16, 0x8537248, 8000) = -1 EAGAIN (Resource
temporarily unavailable)
29311 gettimeofday({1361405772, 896880}, NULL) = 0
29311 gettimeofday({1361405772, 896933}, NULL) = 0
BTW I am now on dev@apr, I'll leave it to you Rainer if you want this
continued on both or either lists.
Cheers
Noel
Re: [VOTE] Release Apache httpd 2.4.4 as GA
Posted by Noel Butler <no...@ausics.net>.
On Wed, 2013-02-20 at 23:56 +0100, Rainer Jung wrote:
>
> That's strange, the additional stderr output
>
> "crypt_r returned NULL"
>
> or
>
> "crypt_r returned '%s'"
>
> is not shown here.
>
Indeed, I'm running :
LogLevel debug auth_basic:trace8 authn_dbd:trace8
Briefly ran trace8 globally, but only briefly for obvious reasons, my
eyes were starting to bleed :)
> As an alternative one could use strace to check the call to crypt_r and
strace only shows...
29311 gettimeofday({1361405772, 894610}, NULL) = 0
29311 poll([{fd=17, events=POLLIN|POLLPRI}], 1, 0) = 0 (Timeout)
29311 write(17, "*\0\0\0\26SELECT Password FROM users WHERE User
= ?"..., 46) = 46
29311 read(17, "\f\0\0\1\0\1\0\0\0\1\0\1\0\0\0\0\27\0\0\2\3def\0\0\0
\1?\0\f?\0\0\0\0\0\375\200\0\0\0\0\5\0\0\3\376\0\0\2\0007\0\0\4\3def
\7members\5users\5users\10Password\10Password\f\10\0\0\1\0\0\375\201\20
\0\0\0\5\0\0\5\376\0\0\2\0"..., 16384) = 120
29311 poll([{fd=17, events=POLLIN|POLLPRI}], 1, 0) = 0 (Timeout)
29311 poll([{fd=17, events=POLLIN|POLLPRI}], 1, 0) = 0 (Timeout)
29311 write(17, "\23\0\0\0\27\1\0\0\0\0\1\0\0\0\0\1\375\0\4noel"..., 23)
= 23
29311 read(17, "\1\0\0\1\0017\0\0\2\3def\7members\5users\5users
\10Password\10Password\f\10\0\0\1\0\0\375\201\20\0\0\0\5\0\0\3\376\0\0\2
\0m\0\0\4\0\0j$6$xxxxxxxxxxxx\5\0\0\5\376\0\0\2\0"..., 16384) = 195
29311 gettimeofday({1361405772, 895721}, NULL) = 0
29311 write(8, "[Thu Feb 21 10:16:12.895721 2013] [authn_dbd:trace2]
[pid 29307:tid 3046349680] mod_authn_dbd.c(178): [client
fd1d:c01d:1ce::145:59592] Got hashed password '$6$xxxxxxxxxxxxx' for
user 'noel'\n"..., 281) = 281
29311 gettimeofday({1361405772, 895975}, NULL) = 0
29311 write(8, "[Thu Feb 21 10:16:12.895975 2013] [authn_dbd:debug] [pid
29307:tid 3046349680] mod_authn_dbd.c(199): (70024)passwords do not
match: [client fd1d:c01d:1ce::145:59592] Call to apr_password_validate
for user 'noel' and hashed password '$6$xxxxxxxxxxx"..., 368) = 368
29311 gettimeofday({1361405772, 896212}, NULL) = 0
29311 write(8, "[Thu Feb 21 10:16:12.896212 2013] [auth_basic:trace1]
[pid 29307:tid 3046349680] mod_auth_basic.c(246): [client
fd1d:c01d:1ce::145:59592] Checking password for user 'noel' using
provider 'dbd', result: 0\n"..., 204) = 204
29311 gettimeofday({1361405772, 896399}, NULL) = 0
29311 write(8, "[Thu Feb 21 10:16:12.896399 2013] [auth_basic:error]
[pid 29307:tid 3046349680] [client fd1d:c01d:1ce::145:59592] AH01617:
user noel: authentication failure for \"/\": Password Mismatch\n"...,
184) = 184
29311 gettimeofday({1361405772, 896750}, NULL) = 0
29311 read(16, 0x8537248, 8000) = -1 EAGAIN (Resource
temporarily unavailable)
29311 gettimeofday({1361405772, 896880}, NULL) = 0
29311 gettimeofday({1361405772, 896933}, NULL) = 0
BTW I am now on dev@apr, I'll leave it to you Rainer if you want this
continued on both or either lists.
Cheers
Noel