You are viewing a plain text version of this content. The canonical link for it is here.
Posted to bugs@httpd.apache.org by bu...@apache.org on 2019/05/13 15:35:18 UTC
[Bug 63426] New: Excessive logging: AH02227: Failed to set r->user
to 'SSL_CLIENT_S_DN' & AH02261: Re-negotiation handshake failed
https://bz.apache.org/bugzilla/show_bug.cgi?id=63426
Bug ID: 63426
Summary: Excessive logging: AH02227: Failed to set r->user to
'SSL_CLIENT_S_DN' & AH02261: Re-negotiation handshake
failed
Product: Apache httpd-2
Version: 2.4.39
Hardware: PC
OS: Linux
Status: NEW
Severity: normal
Priority: P2
Component: mod_ssl
Assignee: bugs@httpd.apache.org
Reporter: tlhackque@yahoo.com
Target Milestone: ---
My error log file is being flooded with what seem to be, at best,
debug level messages of two sorts. (At loglevel warn)
The configuration has VerifyClient optional OR no authtentication
as shown below.
Functionally, a cgi script provides additional content when a
certificate is provided by the client. But no certificate,
password, or other authentication/authorization is required
for "normal" access to the location.
The first message flooding the logs is:
AH02227: Failed to set r->user to 'SSL_CLIENT_S_DN'
is generated when no certificate is provided. This is
expected in this case. There is no username to set
unless a certificate is provided. And the certificate is
optional.
I believe that either:
- this message should not be generated in this case; or
- the message should be removed; or
- the severity should be downgraded to trace level
In the patch below, I demote it to trace6, as it is
phrased as a debugging message rather than one actionable
by an httpd administrator.
The second message is :
AH02261: Re-negotiation handshake failed
This seems to be a browser behavior - despite the message,
the connection is eventually established and the content
displayed. Below is a trace (I've edited for length and
clarity).
I believe that what happens is:
- The browser connects
- Httpd sees the Optional client verification and initiates
renegotiation
- The browser prompts to see whether a certificate is to be
provided - and does not complete the renegotiation. I
think it closes the connection.
- The browser retries (with or without a certificate), and
completes the renegotiation.
Since at the end of the day, both parties (and the user) are
happy, and this happens on every ("new") connection, the log
messages are not helpful. "new" - at least, new browser
instance - a given instance seems to remember what to do...
most of the time.
Perhaps it is possible for httpd to distinguish this case
from cases where renegotiation is a hard failure. I
simple-mindedly reduced the severity to DEBUG.
In any case, it does not appear to be an issue that
either the browser user or httpd administrator can
fix. So the message is not helpful - in addition,
it consumes resources.
Trace (Chrome, OpenSSL 1.1.1b 26 Feb 2019, httpd 2.4.39)
from the httpd error log, trace level 6.
(startup)
OpenSSL: Handshake: start
OpenSSL: Loop: before SSL initialization
OpenSSL: read 5/5 bytes from BIO
OpenSSL: read 512/512 bytes from BIO
OpenSSL: Loop: before SSL initialization
ssl_engine_kernel.c(2043): Inter-Process Session Cache: request=GET
status=MISSED id=..
459941f48f0cc128f (session renewal)
AH02043: SSL virtual host for servername ... found
(stapling)
AH02043: SSL virtual host for servername ... found
OpenSSL: Loop: SSLv3/TLS read client hello
OpenSSL: Loop: SSLv3/TLS write server hello
OpenSSL: Loop: SSLv3/TLS write certificate
OpenSSL: Loop: SSLv3/TLS write certificate status
OpenSSL: Loop: SSLv3/TLS write key exchange
OpenSSL: write 3696/3696 bytes to BIO
OpenSSL: Loop: SSLv3/TLS write server done
OpenSSL: read 5/5 bytes from BIO
OpenSSL: read 37/37 bytes from BIO
OpenSSL: Loop: SSLv3/TLS write server done
OpenSSL: read 5/5 bytes from BIO
OpenSSL: read 1/1 bytes from BIO
OpenSSL: Loop: SSLv3/TLS read client key exchange
OpenSSL: read 5/5 bytes from BIO
OpenSSL: read 32/32 bytes from BIO
OpenSSL: Loop: SSLv3/TLS read change cipher spec
OpenSSL: Loop: SSLv3/TLS read finished
OpenSSL: Loop: SSLv3/TLS write session ticket
OpenSSL: Loop: SSLv3/TLS write change cipher spec
OpenSSL: write 282/282 bytes to BIO
OpenSSL: Loop: SSLv3/TLS write finished
OpenSSL: Handshake: done
AH02041: Protocol: TLSv1.2, Cipher: ECDHE-ECDSA-CHACHA20-POLY1305 (256/256
bits)
OpenSSL: read 5/5 bytes from BIO
OpenSSL: read 453/453 bytes from BIO
AH02034: Initial (No.1) HTTPS request received for child 0
AH02255: Changed client verification type will force renegotiation
AH02221: Requesting connection re-negotiation
OpenSSL: I/O error, 5 bytes expected to read on BIO
AH02260: Performing full renegotiation: complete handshake protocol (client
does support secure renegotiation)
OpenSSL: Handshake: start
OpenSSL: Loop: SSL negotiation finished successfully
OpenSSL: write 25/25 bytes to BIO
OpenSSL: Loop: SSLv3/TLS write hello request
OpenSSL: Handshake: done
AH02041: Protocol: TLSv1.2, Cipher: ECDHE-ECDSA-CHACHA20-POLY1305 (256/256
bits)
AH02226: Awaiting re-negotiation handshake
OpenSSL: read 5/5 bytes from BIO
OpenSSL: read 528/528 bytes from BIO
OpenSSL: Handshake: start
OpenSSL: Loop: SSL negotiation finished successfully
OpenSSL: Loop: SSL negotiation finished successfully
AH02043: SSL virtual host for servername ... found
(stapling)
OpenSSL: Loop: SSLv3/TLS read client hello
OpenSSL: Loop: SSLv3/TLS write server hello
OpenSSL: Loop: SSLv3/TLS write certificate
OpenSSL: Loop: SSLv3/TLS write certificate status
OpenSSL: Loop: SSLv3/TLS write key exchange
OpenSSL: Loop: SSLv3/TLS write certificate request
OpenSSL: write 3985/3985 bytes to BIO
OpenSSL: Loop: SSLv3/TLS write server done
OpenSSL: I/O error, 5 bytes expected to read on BIO
OpenSSL: Exit: error in SSLv3/TLS write server done
AH02261: Re-negotiation handshake failed
## This is where the browser prompts for a decision on whether to
## supply a certificate. I can't tell if the prompt is before or
## after the AH02261. In any case, here I click "cancel"
## It appears that the browser closes the connection...
coalesce: have 0 bytes, adding 233 more
coalesce: have 233 bytes, adding 331 more
coalesce: passing on 564 bytes
OpenSSL: I/O error, 5 bytes expected to read on BIO
OpenSSL: Exit: error in SSLv3/TLS write server done
AH02007: SSL handshake interrupted by system [Hint: Stop button pressed in
browser?!]
AH01998: Connection closed to child 0 with abortive shutdown (server ...)
AH01964: Connection to child 1 established (server ...)
ssl_engine_rand.c(126): Server: Seeding PRNG with 136 bytes of entropy
OpenSSL: Handshake: start
OpenSSL: Loop: before SSL initialization
OpenSSL: read 5/5 bytes from BIO
OpenSSL: read 529/529 bytes from BIO
OpenSSL: Loop: before SSL initialization
AH02043: SSL virtual host for servername ... found
AH02043: SSL virtual host for servername ... found
OpenSSL: Loop: SSLv3/TLS read client hello
OpenSSL: Loop: SSLv3/TLS write server hello
OpenSSL: Loop: SSLv3/TLS write change cipher spec
OpenSSL: write 148/148 bytes to BIO
OpenSSL: Loop: SSLv3/TLS write finished
OpenSSL: read 5/5 bytes from BIO
OpenSSL: read 1/1 bytes from BIO
OpenSSL: Loop: SSLv3/TLS write finished
OpenSSL: read 5/5 bytes from BIO
OpenSSL: read 32/32 bytes from BIO
OpenSSL: Loop: SSLv3/TLS read change cipher spec
OpenSSL: Loop: SSLv3/TLS read finished
OpenSSL: Handshake: done
AH02041: Protocol: TLSv1.2, Cipher: ECDHE-ECDSA-CHACHA20-POLY1305 (256/256
bits)
OpenSSL: read 5/5 bytes from BIO
OpenSSL: read 453/453 bytes from BIO
AH02034: Initial (No.1) HTTPS request received for child 1 (server ...)
AH02255: Changed client verification type will force renegotiation
AH02221: Requesting connection re-negotiation
OpenSSL: I/O error, 5 bytes expected to read on BIO
AH02260: Performing full renegotiation: complete handshake protocol (client
does support secure renegotiation)
OpenSSL: Handshake: start
OpenSSL: Loop: SSL negotiation finished successfully
OpenSSL: write 25/25 bytes to BIO
OpenSSL: Loop: SSLv3/TLS write hello request
OpenSSL: Handshake: done
AH02041: Protocol: TLSv1.2, Cipher: ECDHE-ECDSA-CHACHA20-POLY1305 (256/256
bits)
AH02226: Awaiting re-negotiation handshake
OpenSSL: read 5/5 bytes from BIO
OpenSSL: read 528/528 bytes from BIO
OpenSSL: Handshake: start
OpenSSL: Loop: SSL negotiation finished successfully
OpenSSL: Loop: SSL negotiation finished successfully
AH02043: SSL virtual host for servername ... found
(stapling)
OpenSSL: Loop: SSLv3/TLS read client hello
OpenSSL: Loop: SSLv3/TLS write server hello
OpenSSL: Loop: SSLv3/TLS write certificate
OpenSSL: Loop: SSLv3/TLS write certificate status
OpenSSL: Loop: SSLv3/TLS write key exchange
OpenSSL: Loop: SSLv3/TLS write certificate request
OpenSSL: write 3984/3984 bytes to BIO
OpenSSL: Loop: SSLv3/TLS write server done
OpenSSL: read 5/5 bytes from BIO
OpenSSL: read 60/60 bytes from BIO
OpenSSL: Loop: SSLv3/TLS write server done
OpenSSL: Loop: SSLv3/TLS read client certificate
OpenSSL: read 5/5 bytes from BIO
OpenSSL: read 17/17 bytes from BIO
OpenSSL: Loop: SSLv3/TLS read client key exchange
OpenSSL: read 5/5 bytes from BIO
OpenSSL: read 32/32 bytes from BIO0
OpenSSL: Loop: SSLv3/TLS read change cipher spec
OpenSSL: Loop: SSLv3/TLS read finished
OpenSSL: Loop: SSLv3/TLS write change cipher spec
OpenSSL: write 59/59 bytes to BIO
OpenSSL: Loop: SSLv3/TLS write finished
ssl_engine_kernel.c(2043): Inter-Process Session Cache: request=SET status=OK
id=7... timeout=3600s (session caching)
OpenSSL: Handshake: done
AH02041: Protocol: TLSv1.2, Cipher: ECDHE-ECDSA-CHACHA20-POLY1305 (256/256
bits)
AH02227: Failed to set r->user to 'SSL_CLIENT_S_DN'
coalesce: have 0 bytes, adding 541 more
coalesce: passing on 541 bytes
OpenSSL: write 562/562 bytes to BIO
OpenSSL: write 3030/3030 bytes to BIO
OpenSSL: I/O error, 5 bytes expected to read on BIO
OpenSSL: read 5/5 bytes from BIO
OpenSSL: read 491/491 bytes from BIO
AH02034: Subsequent (No.2) HTTPS request received for child 1 (server ...),
referer: ...
AH02227: Failed to set r->user to 'SSL_CLIENT_S_DN', referer: ...
AH01964: Connection to child 2 established (server ...)
ssl_engine_rand.c(126): Server: Seeding PRNG with 136 bytes of entropy
OpenSSL: Handshake: start
OpenSSL: Loop: before SSL initialization
OpenSSL: read 5/5 bytes from BIO
OpenSSL: read 529/529 bytes from BIO
OpenSSL: Loop: before SSL initialization
AH02043: SSL virtual host for servername ... found
AH02043: SSL virtual host for servername ... found
coalesce: have 0 bytes, adding 398 more
coalesce: passing on 398 bytes
OpenSSL: write 419/419 bytes to BIO
OpenSSL: write 2125/2125 bytes to BIO
OpenSSL: I/O error, 5 bytes expected to read on BIO
OpenSSL: Loop: SSLv3/TLS read client hello
AH01964: Connection to child 3 established (server ...)
OpenSSL: read 5/5 bytes from BIO
ssl_engine_rand.c(126): Server: Seeding PRNG with 136 bytes of entropy
OpenSSL: read 479/479 bytes from BIO
AH02034: Subsequent (No.3) HTTPS request received for child 1 (server ...),
referer: ...
OpenSSL: Handshake: start
OpenSSL: Loop: SSLv3/TLS write server hello
OpenSSL: Loop: SSLv3/TLS write change cipher spec
OpenSSL: write 148/148 bytes to BIO
OpenSSL: Loop: SSLv3/TLS write finished
AH02227: Failed to set r->user to 'SSL_CLIENT_S_DN', referer: ...
OpenSSL: Loop: before SSL initialization
OpenSSL: read 5/5 bytes from BIO
OpenSSL: read 5/5 bytes from BIO
OpenSSL: read 1/1 bytes from BIO
OpenSSL: Loop: SSLv3/TLS write finished
OpenSSL: read 5/5 bytes from BIO
OpenSSL: read 32/32 bytes from BIO
OpenSSL: Loop: SSLv3/TLS read change cipher spec
OpenSSL: Loop: SSLv3/TLS read finished
OpenSSL: Handshake: done
AH02041: Protocol: TLSv1.2, Cipher: ECDHE-ECDSA-CHACHA20-POLY1305 (256/256
bits)
OpenSSL: read 5/5 bytes from BIO
OpenSSL: read 495/495 bytes from BIO
OpenSSL: read 529/529 bytes from BIO
OpenSSL: Loop: before SSL initialization
AH02043: SSL virtual host for servername ... found
AH02043: SSL virtual host for servername ... found
OpenSSL: Loop: SSLv3/TLS read client hello
OpenSSL: Loop: SSLv3/TLS write server hello
OpenSSL: Loop: SSLv3/TLS write change cipher spec
OpenSSL: write 148/148 bytes to BIO...
OpenSSL: Loop: SSLv3/TLS write finished
OpenSSL: read 5/5 bytes from BIO...
OpenSSL: read 1/1 bytes from BIO...
OpenSSL: Loop: SSLv3/TLS write finished
OpenSSL: read 5/5 bytes from BIO...
OpenSSL: read 32/32 bytes from BIO...
OpenSSL: Loop: SSLv3/TLS read change cipher spec
OpenSSL: Loop: SSLv3/TLS read finished
OpenSSL: Handshake: done
AH02041: Protocol: TLSv1.2, Cipher: ECDHE-ECDSA-CHACHA20-POLY1305 (256/256
bits)
AH02034: Initial (No.1) HTTPS request received for child 2 (server ...),
referer: ...
coalesce: have 0 bytes, adding 415 more
coalesce: passing on 415 bytes
OpenSSL: write 436/436 bytes to BIO
OpenSSL: write 10230/10230 bytes to BIO
OpenSSL: I/O error, 5 bytes expected to read on BIO
AH02255: Changed client verification type will force renegotiation, referer:
...
AH02221: Requesting connection re-negotiation, referer: ...
OpenSSL: I/O error, 5 bytes expected to read on BIO
AH02260: Performing full renegotiation: complete handshake protocol (client
does support secure renegotiation), referer: ...
OpenSSL: Handshake: start
OpenSSL: Loop: SSL negotiation finished successfully
OpenSSL: write 25/25 bytes to BIO
OpenSSL: Loop: SSLv3/TLS write hello request
OpenSSL: Handshake: done
AH02041: Protocol: TLSv1.2, Cipher: ECDHE-ECDSA-CHACHA20-POLY1305 (256/256
bits)
AH02226: Awaiting re-negotiation handshake, referer: ..
OpenSSL: read 5/5 bytes from BIO
OpenSSL: read 528/528 bytes from BIO
OpenSSL: Handshake: start
OpenSSL: Loop: SSL negotiation finished successfully
OpenSSL: Loop: SSL negotiation finished successfully
AH02043: SSL virtual host for servername ... found
OpenSSL: Loop: SSLv3/TLS write server hello
OpenSSL: Loop: SSLv3/TLS write change cipher spec
(Things continue uneventfully from here -- until the next
browser connects.)
Loglevel warn # Normal
Loglevel warn ssl:trace6 # Used for the above trace
<LocationMatch "^/...$">
SSLVerifyClient optional
SSLVerifyDepth 10
SSLOptions +StrictRequire +OptRenegotiate
SSLRequireSSL
AuthName "... Administration"
AuthType Basic
AuthBasicFake "%{SSL_CLIENT_S_DN}" "password"
AuthBasicProvider file
AuthUserFile "/..."
SSLUserName SSL_CLIENT_S_DN
<RequireAny>
<RequireALL>
require ssl-verify-client
<RequireAll>
Require valid-user
Require expr %{SSL_CLIENT_VERIFY} eq "SUCCESS" && \
...
</RequireAll>
</RequireAll>
require all granted
</RequireAny>
</LocationMatch>
--- modules/ssl/ssl_engine_kernel.c.orig 2019-03-20 11:45:16.000000000
-0400
+++ modules/ssl/ssl_engine_kernel.c 2019-05-13 09:41:53.000000000 -0400
@@ -1008,11 +1008,11 @@
SSL_peek(ssl, peekbuf, 0);
sslconn->reneg_state = RENEG_REJECT;
if (!SSL_is_init_finished(ssl)) {
- ap_log_rerror(APLOG_MARK, APLOG_ERR, 0, r, APLOGNO(02261)
+ ap_log_rerror(APLOG_MARK, APLOG_DEBUG, 0, r, APLOGNO(02261)
"Re-negotiation handshake failed");
ssl_log_ssl_error(SSLLOG_MARK, APLOG_ERR, r->server);
r->connection->keepalive = AP_CONN_CLOSE;
return HTTP_FORBIDDEN;
@@ -1274,11 +1274,11 @@
char *val = ssl_var_lookup(r->pool, r->server, r->connection,
r, (char *)dc->szUserName);
if (val && val[0])
r->user = val;
else
- ap_log_rerror(APLOG_MARK, APLOG_WARNING, 0, r, APLOGNO(02227)
+ ap_log_rerror(APLOG_MARK, APLOG_TRACE6, 0, r, APLOGNO(02227)
"Failed to set r->user to '%s'", dc->szUserName);
}
/*
* Check SSLRequire boolean expressions
--
You are receiving this mail because:
You are the assignee for the bug.
---------------------------------------------------------------------
To unsubscribe, e-mail: bugs-unsubscribe@httpd.apache.org
For additional commands, e-mail: bugs-help@httpd.apache.org