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.