Closed Bug 502781 Opened 16 years ago Closed 10 years ago

fatal, Firefox-only "ssl_error_handshake_unexpected_alert" error when accessing SSL site

Categories

(NSS :: Libraries, defect)

Product:
NSS
Component:
Libraries
Platform:
x86
Linux
Type:
defect
Priority:
Not set
Severity:
major

Tracking

(Not tracked)

Status:
RESOLVED INVALID

People

(Reporter: u350923, Unassigned)

Details

User-Agent: Mozilla/5.0 (X11; U; Linux i686; en-US; rv:1.9) Gecko/2008052906 Firefox/3.0 Build Identifier: Mozilla/5.0 (X11; U; Linux i686; en-US; rv:1.9) Gecko/2008052906 Firefox/3.0 hi, i'm getting a Shiretoko/OSX-only (i.e., Safari/OSX has no problems) SSL error, "Re-negotiation handshake failed: Not accepted by client!?" when connecting to an Apache + mod_ssl site, running, apache2-2.2.11-10.1 apache2-worker-2.2.11-10.1 installed from openSUSE 11.1 repos, http://download.opensuse.org/repositories/Apache/openSUSE_11.1 fwiw, it's a Drupal site, most of which has no probs. But, on one page, exec'ing one task (modifying theme settings), I get the following error, Secure Connection Failed An error occurred during a connection to www.mydomain.net. SSL peer was not expecting a handshake message it received. (Error code: ssl_error_handshake_unexpected_alert) the problem occurs, fatally, only in Shiretoko/OSX -- again, _not_ in Safari/OSX. it's 100% reproducible on similarly configured servers, with fresh installs of Apache & Drupal 6.13. i've included, below, the apache logs for case: (A) Firefox case: (B) Safari i'm not at all clear what's _causing_ the error, only that it manifests only when using FF. i'm happy to provide add'l info, once clear what's helpful. any insights/suggestions are appreciated. thanks! (A) Firefox @ browser, Secure Connection Failed An error occurred during a connection to www.mydomain.net. SSL peer was not expecting a handshake message it received. (Error code: ssl_error_handshake_unexpected_alert) @ logs, [Mon Jul 06 21:57:29 2009] [info] [client 11.22.33.44] Connection to child 0 established (server mydomain.net:443) [Mon Jul 06 21:57:29 2009] [info] Seeding PRNG with 1024 bytes of entropy [Mon Jul 06 21:57:29 2009] [info] Initial (No.1) HTTPS request received for child 0 (server mydomain.net:443) [Mon Jul 06 21:57:29 2009] [info] Requesting connection re-negotiation [Mon Jul 06 21:57:29 2009] [info] Awaiting re-negotiation handshake [Mon Jul 06 21:57:29 2009] [error] Re-negotiation handshake failed: Not accepted by client!? [Mon Jul 06 21:57:29 2009] [error] [client 11.22.33.44] (103)Software caused connection abort: could not read request body for SSL buffer, referer: https://www.mydomain.net/main/admin/build/themes/settings/mydomain_zen [Mon Jul 06 21:57:29 2009] [error] [client 11.22.33.44] could not buffer message body to allow SSL renegotiation to proceed, referer: https://www.mydomain.net/main/admin/build/themes/settings/mydomain_zen (B) Safari @ browser, (page displays as expected) @ logs, [Mon Jul 06 21:55:12 2009] [info] [client 11.22.33.44] Connection to child 0 established (server mydomain.net:443) [Mon Jul 06 21:55:12 2009] [info] Seeding PRNG with 1024 bytes of entropy [Mon Jul 06 21:55:12 2009] [info] Initial (No.1) HTTPS request received for child 0 (server mydomain.net:443) [Mon Jul 06 21:55:13 2009] [info] [client 11.22.33.44] Connection to child 2 established (server mydomain.net:443) [Mon Jul 06 21:55:13 2009] [info] Seeding PRNG with 1024 bytes of entropy [Mon Jul 06 21:55:13 2009] [info] Initial (No.1) HTTPS request received for child 2 (server mydomain.net:443) [Mon Jul 06 21:55:13 2009] [info] Subsequent (No.2) HTTPS request received for child 2 (server mydomain.net:443) [Mon Jul 06 21:55:15 2009] [info] Subsequent (No.3) HTTPS request received for child 2 (server mydomain.net:443) [Mon Jul 06 21:55:15 2009] [info] [client 11.22.33.44] Connection closed to child 0 with standard shutdown (server mydomain.net:443) [Mon Jul 06 21:55:16 2009] [info] Subsequent (No.4) HTTPS request received for child 2 (server mydomain.net:443) [Mon Jul 06 21:55:16 2009] [info] [client 11.22.33.44] Connection to child 4 established (server mydomain.net:443) [Mon Jul 06 21:55:16 2009] [info] Seeding PRNG with 1024 bytes of entropy [Mon Jul 06 21:55:16 2009] [info] [client 11.22.33.44] Connection to child 3 established (server mydomain.net:443) [Mon Jul 06 21:55:16 2009] [info] Seeding PRNG with 1024 bytes of entropy [Mon Jul 06 21:55:16 2009] [info] [client 11.22.33.44] Connection to child 1 established (server mydomain.net:443) [Mon Jul 06 21:55:16 2009] [info] Seeding PRNG with 1024 bytes of entropy [Mon Jul 06 21:55:16 2009] [info] Initial (No.1) HTTPS request received for child 3 (server mydomain.net:443) [Mon Jul 06 21:55:16 2009] [info] Initial (No.1) HTTPS request received for child 4 (server mydomain.net:443) [Mon Jul 06 21:55:16 2009] [info] [client 11.22.33.44] Connection to child 0 established (server mydomain.net:443) [Mon Jul 06 21:55:16 2009] [info] Seeding PRNG with 1024 bytes of entropy [Mon Jul 06 21:55:16 2009] [info] Initial (No.1) HTTPS request received for child 1 (server mydomain.net:443) [Mon Jul 06 21:55:16 2009] [info] Subsequent (No.5) HTTPS request received for child 2 (server mydomain.net:443) [Mon Jul 06 21:55:16 2009] [info] Initial (No.1) HTTPS request received for child 0 (server mydomain.net:443) [Mon Jul 06 21:55:16 2009] [info] Subsequent (No.2) HTTPS request received for child 3 (server mydomain.net:443) [Mon Jul 06 21:55:16 2009] [info] Subsequent (No.2) HTTPS request received for child 4 (server mydomain.net:443) [Mon Jul 06 21:55:16 2009] [info] Subsequent (No.2) HTTPS request received for child 1 (server mydomain.net:443) [Mon Jul 06 21:55:16 2009] [info] Subsequent (No.2) HTTPS request received for child 0 (server mydomain.net:443) [Mon Jul 06 21:55:16 2009] [info] [client 11.22.33.44] Connection to child 32 established (server mydomain.net:443) [Mon Jul 06 21:55:16 2009] [info] Seeding PRNG with 1024 bytes of entropy [Mon Jul 06 21:55:16 2009] [info] [client 11.22.33.44] Connection to child 33 established (server mydomain.net:443) [Mon Jul 06 21:55:16 2009] [info] Seeding PRNG with 1024 bytes of entropy [Mon Jul 06 21:55:16 2009] [info] [client 11.22.33.44] Connection to child 34 established (server mydomain.net:443) [Mon Jul 06 21:55:16 2009] [info] Seeding PRNG with 1024 bytes of entropy [Mon Jul 06 21:55:16 2009] [info] Subsequent (No.6) HTTPS request received for child 2 (server mydomain.net:443) [Mon Jul 06 21:55:16 2009] [info] Subsequent (No.3) HTTPS request received for child 3 (server mydomain.net:443) [Mon Jul 06 21:55:17 2009] [info] Subsequent (No.3) HTTPS request received for child 4 (server mydomain.net:443) [Mon Jul 06 21:55:17 2009] [info] Subsequent (No.3) HTTPS request received for child 1 (server mydomain.net:443) [Mon Jul 06 21:55:17 2009] [info] Subsequent (No.3) HTTPS request received for child 0 (server mydomain.net:443) [Mon Jul 06 21:55:17 2009] [info] Subsequent (No.7) HTTPS request received for child 2 (server mydomain.net:443) [Mon Jul 06 21:55:17 2009] [info] Initial (No.1) HTTPS request received for child 34 (server mydomain.net:443) [Mon Jul 06 21:55:17 2009] [info] Subsequent (No.4) HTTPS request received for child 4 (server mydomain.net:443) [Mon Jul 06 21:55:17 2009] [info] Subsequent (No.4) HTTPS request received for child 1 (server mydomain.net:443) [Mon Jul 06 21:55:17 2009] [info] Subsequent (No.4) HTTPS request received for child 0 (server mydomain.net:443) [Mon Jul 06 21:55:17 2009] [info] Subsequent (No.8) HTTPS request received for child 2 (server mydomain.net:443) [Mon Jul 06 21:55:17 2009] [info] Initial (No.1) HTTPS request received for child 32 (server mydomain.net:443) [Mon Jul 06 21:55:17 2009] [info] Initial (No.1) HTTPS request received for child 33 (server mydomain.net:443) [Mon Jul 06 21:55:17 2009] [info] Subsequent (No.4) HTTPS request received for child 3 (server mydomain.net:443) [Mon Jul 06 21:55:17 2009] [info] Subsequent (No.2) HTTPS request received for child 34 (server mydomain.net:443) [Mon Jul 06 21:55:18 2009] [info] Subsequent (No.5) HTTPS request received for child 4 (server mydomain.net:443) [Mon Jul 06 21:55:18 2009] [info] Subsequent (No.5) HTTPS request received for child 1 (server mydomain.net:443) [Mon Jul 06 21:55:18 2009] [info] Subsequent (No.5) HTTPS request received for child 0 (server mydomain.net:443) [Mon Jul 06 21:55:18 2009] [info] Subsequent (No.9) HTTPS request received for child 2 (server mydomain.net:443) [Mon Jul 06 21:55:18 2009] [info] Subsequent (No.2) HTTPS request received for child 32 (server mydomain.net:443) [Mon Jul 06 21:55:18 2009] [info] Subsequent (No.2) HTTPS request received for child 33 (server mydomain.net:443) [Mon Jul 06 21:55:18 2009] [info] Subsequent (No.5) HTTPS request received for child 3 (server mydomain.net:443) [Mon Jul 06 21:55:18 2009] [info] Subsequent (No.3) HTTPS request received for child 34 (server mydomain.net:443) [Mon Jul 06 21:55:18 2009] [info] Subsequent (No.6) HTTPS request received for child 4 (server mydomain.net:443) [Mon Jul 06 21:55:18 2009] [info] Subsequent (No.6) HTTPS request received for child 1 (server mydomain.net:443) [Mon Jul 06 21:55:18 2009] [info] Subsequent (No.6) HTTPS request received for child 0 (server mydomain.net:443) [Mon Jul 06 21:55:18 2009] [info] Subsequent (No.10) HTTPS request received for child 2 (server mydomain.net:443) [Mon Jul 06 21:55:18 2009] [info] Subsequent (No.3) HTTPS request received for child 32 (server mydomain.net:443) [Mon Jul 06 21:55:18 2009] [info] Subsequent (No.3) HTTPS request received for child 33 (server mydomain.net:443) [Mon Jul 06 21:55:19 2009] [info] Subsequent (No.7) HTTPS request received for child 1 (server mydomain.net:443) [Mon Jul 06 21:55:19 2009] [info] Subsequent (No.11) HTTPS request received for child 2 (server mydomain.net:443) [Mon Jul 06 21:55:19 2009] [info] Subsequent (No.4) HTTPS request received for child 34 (server mydomain.net:443) [Mon Jul 06 21:55:19 2009] [info] Subsequent (No.4) HTTPS request received for child 33 (server mydomain.net:443) [Mon Jul 06 21:55:19 2009] [info] Subsequent (No.4) HTTPS request received for child 32 (server mydomain.net:443) [Mon Jul 06 21:55:19 2009] [info] Subsequent (No.6) HTTPS request received for child 3 (server mydomain.net:443) [Mon Jul 06 21:55:19 2009] [info] Subsequent (No.5) HTTPS request received for child 33 (server mydomain.net:443) [Mon Jul 06 21:55:19 2009] [info] Subsequent (No.12) HTTPS request received for child 2 (server mydomain.net:443) [Mon Jul 06 21:55:19 2009] [info] Subsequent (No.5) HTTPS request received for child 32 (server mydomain.net:443) [Mon Jul 06 21:55:19 2009] [info] Subsequent (No.13) HTTPS request received for child 2 (server mydomain.net:443) [Mon Jul 06 21:55:19 2009] [info] Subsequent (No.6) HTTPS request received for child 32 (server mydomain.net:443) [Mon Jul 06 21:55:19 2009] [info] Subsequent (No.5) HTTPS request received for child 34 (server mydomain.net:443) [Mon Jul 06 21:55:20 2009] [info] Subsequent (No.14) HTTPS request received for child 2 (server mydomain.net:443) [Mon Jul 06 21:55:20 2009] [info] Subsequent (No.6) HTTPS request received for child 34 (server mydomain.net:443) [Mon Jul 06 21:55:20 2009] [info] Subsequent (No.7) HTTPS request received for child 32 (server mydomain.net:443) [Mon Jul 06 21:55:21 2009] [info] Subsequent (No.15) HTTPS request received for child 2 (server mydomain.net:443) [Mon Jul 06 21:55:21 2009] [info] Subsequent (No.7) HTTPS request received for child 34 (server mydomain.net:443) [Mon Jul 06 21:55:21 2009] [info] Subsequent (No.8) HTTPS request received for child 32 (server mydomain.net:443) [Mon Jul 06 21:55:21 2009] [info] Subsequent (No.6) HTTPS request received for child 33 (server mydomain.net:443) [Mon Jul 06 21:55:21 2009] [info] Subsequent (No.16) HTTPS request received for child 2 (server mydomain.net:443) [Mon Jul 06 21:55:21 2009] [info] Subsequent (No.8) HTTPS request received for child 34 (server mydomain.net:443) [Mon Jul 06 21:55:21 2009] [info] Subsequent (No.9) HTTPS request received for child 32 (server mydomain.net:443) [Mon Jul 06 21:55:21 2009] [info] Subsequent (No.7) HTTPS request received for child 33 (server mydomain.net:443) [Mon Jul 06 21:55:21 2009] [info] Subsequent (No.17) HTTPS request received for child 2 (server mydomain.net:443) [Mon Jul 06 21:55:21 2009] [info] Subsequent (No.18) HTTPS request received for child 2 (server mydomain.net:443) [Mon Jul 06 21:55:21 2009] [info] Subsequent (No.10) HTTPS request received for child 32 (server mydomain.net:443) [Mon Jul 06 21:55:21 2009] [info] Subsequent (No.8) HTTPS request received for child 33 (server mydomain.net:443) [Mon Jul 06 21:55:21 2009] [info] Subsequent (No.9) HTTPS request received for child 34 (server mydomain.net:443) [Mon Jul 06 21:55:21 2009] [info] Subsequent (No.11) HTTPS request received for child 32 (server mydomain.net:443) [Mon Jul 06 21:55:21 2009] [info] Subsequent (No.10) HTTPS request received for child 34 (server mydomain.net:443) [Mon Jul 06 21:55:23 2009] [info] [client 11.22.33.44] (70007)The timeout specified has expired: SSL input filter read failed. [Mon Jul 06 21:55:23 2009] [info] [client 11.22.33.44] Connection closed to child 4 with standard shutdown (server mydomain.net:443) [Mon Jul 06 21:55:23 2009] [info] [client 11.22.33.44] (70007)The timeout specified has expired: SSL input filter read failed. [Mon Jul 06 21:55:23 2009] [info] [client 11.22.33.44] Connection closed to child 0 with standard shutdown (server mydomain.net:443) [Mon Jul 06 21:55:24 2009] [info] [client 11.22.33.44] (70007)The timeout specified has expired: SSL input filter read failed. [Mon Jul 06 21:55:24 2009] [info] [client 11.22.33.44] Connection closed to child 1 with standard shutdown (server mydomain.net:443) [Mon Jul 06 21:55:24 2009] [info] [client 11.22.33.44] (70007)The timeout specified has expired: SSL input filter read failed. [Mon Jul 06 21:55:24 2009] [info] [client 11.22.33.44] Connection closed to child 3 with standard shutdown (server mydomain.net:443) [Mon Jul 06 21:55:26 2009] [info] [client 11.22.33.44] (70007)The timeout specified has expired: SSL input filter read failed. [Mon Jul 06 21:55:26 2009] [info] [client 11.22.33.44] Connection closed to child 2 with standard shutdown (server mydomain.net:443) [Mon Jul 06 21:55:26 2009] [info] [client 11.22.33.44] (70007)The timeout specified has expired: SSL input filter read failed. [Mon Jul 06 21:55:26 2009] [info] [client 11.22.33.44] Connection closed to child 32 with standard shutdown (server mydomain.net:443) [Mon Jul 06 21:55:26 2009] [info] [client 11.22.33.44] (70007)The timeout specified has expired: SSL input filter read failed. [Mon Jul 06 21:55:26 2009] [info] [client 11.22.33.44] Connection closed to child 34 with standard shutdown (server mydomain.net:443) [Mon Jul 06 21:55:26 2009] [info] [client 11.22.33.44] (70007)The timeout specified has expired: SSL input filter read failed. [Mon Jul 06 21:55:26 2009] [info] [client 11.22.33.44] Connection closed to child 33 with standard shutdown (server mydomain.net:443) Reproducible: Always
-> NSS for triage since this sounds like a protocol-layer problem, or possibly an aberrant server config.
Assignee: nobody → nobody
Component: Security → Libraries
Product: Firefox → NSS
QA Contact: firefox → libraries
re: server conf, here's what i'm currently working with: @ httpd.conf, SSLCipherSuite ALL:!ADH:RC4+RSA:+HIGH:+MEDIUM:+LOW:+SSLv2:+EXP:+eNULL SSLMutex default SSLPassPhraseDialog builtin SSLProtocol +TLSv1 SSLRandomSeed connect file:/dev/urandom 1024 SSLRandomSeed startup file:/dev/urandom 1024 SSLSessionCache shmcb:/var/cache/ssl/ssl_scache(1024000) SSLSessionCacheTimeout 300 SSLVerifyClient none AddType application/x-x509-ca-cert .crt AddType application/x-pkcs7-crl .crl @ vhost.conf, SSLEngine on SSLRequireSSL SSLOptions +StrictRequire +OptRenegotiate # SSLRenegBufferSize 262144 SSLCipherSuite AES256-SHA:AES128-SHA SSLRequire %{SSL_CIPHER_USEKEYSIZE} >= 128 SSLCertificateFile /data/etc/ssl/ssl.crt/mydomain.crt SSLCertificateKeyFile /data/etc/ssl/ssl.key/mydomain.key SSLCACertificateFile /data/etc/ssl/ssl.crt/intermediate.crt SSLCACertificatePath /etc/ssl/certs ErrorDocument 403 https://www.mydomain.net <Files ~ "\.(cgi|shtml|php?)$"> SSLOptions +StdEnvVars -ExportCertData </Files> <Directory "/data/webapps/MyDomain/cgi-bin"> SSLOptions +StdEnvVars -ExportCertData </Directory> again, no Safari problems, and _most_ all other SSL access @ my site, even with FF, seems to be OK -- at least it renders in browser without error ...
playing with various non-SSL apache config options, i find if i KeepAlive On MaxKeepAliveRequests 10 -- KeepAliveTimeout 5 ++ KeepAliveTimeout 120 then, @ FF exec of the aforementioned "Save Configuration", i get _no_ immediate browser error, & logs report: [Tue Jul 07 10:41:49 2009] [info] Subsequent (No.8) HTTPS request received for child 4 (server mydomain.net:443) [Tue Jul 07 10:41:50 2009] [info] Subsequent (No.9) HTTPS request received for child 3 (server mydomain.net:443) [Tue Jul 07 10:41:52 2009] [error] [client 11.22.33.44] FastCGI: neither POLLIN nor POLLOUT..., referer: https://www.mydomain.net/main/admin/build/themes/settings/acquia_marina [Tue Jul 07 10:41:55 2009] [info] Subsequent (No.9) HTTPS request received for child 4 (server mydomain.net:443) [Tue Jul 07 10:42:32 2009] [info] Subsequent (No.10) HTTPS request received for child 3 (server mydomain.net:443) [Tue Jul 07 10:43:56 2009] [info] [client 11.22.33.44] (70007)The timeout specified has expired: SSL input filter read failed. [Tue Jul 07 10:43:56 2009] [info] [client 11.22.33.44] Connection closed to child 4 with standard shutdown (server mydomain.net:443) [Tue Jul 07 10:44:32 2009] [info] [client 11.22.33.44] (70007)The timeout specified has expired: SSL input filter read failed. [Tue Jul 07 10:44:32 2009] [info] [client 11.22.33.44] Connection closed to child 3 with standard shutdown (server mydomain.net:443) repeating the "Save Configuration" step no longer causes the browser error -- unless I don't wait "long enough" before the repeat. unclear what that limit is, but ~<= 5 secs and the error repeats. clearly something in FF is unhappy with "a timeout" on my server ... 1st, i'll track down that (new) FastCGI error, and then dig some more.
The server is undoubtedly doing a renegotiation handshake to request client auth. It typically takes the user some time to do a client auth. I suspect your server is giving up WAY too soon. server logs are not terribly helpful for analysis of browser issues. Much better would be a log file from ssltap or ssldump.
hi nelson, On Tue, Jul 7, 2009 at 11:04 PM, <bugzilla-daemon@mozilla.org> wrote: > --- Comment #4 from Nelson Bolyard (:MisterSSL) <nelson@bolyard.me> 2009-07-07 23:04:22 PDT --- > The server is undoubtedly doing a renegotiation handshake to request client > auth. why would the server be requeting client auth? i thought that SSLVerifyClient none should prevent that. does something else in my config trigger that? > It typically takes the user some time to do a client auth. I suspect your > server is giving up WAY too soon. how would that be consistent with Safari not having this issue? different error handling? > server logs are not terribly helpful for analysis of browser issues. > Much better would be a log file from ssltap or ssldump. i'm not in front of that machine, atm ... but, i'll get that done and post back. thanks.
There are VERY few reasons why a server would want to do a second negotiation immediately after successfully doing a first one. The usual reason is that, on the first one, it did not request client auth, but then it received the client's https request, and decided that client auth is required as an access control for the requested asset. So, it does a second negotiation to request client auth. Now, if your server isn't requesting client auth, then why would it request a renegotiation? That's a waste of time, CPU cycles, bandwidth, you name it. IINM, Firefox's default setting for client auth is to prompt the user and ask him what to do. If you have a short timeout for that, you're out of luck. SSLtap and SSLdump are your friends.
Status: UNCONFIRMED → RESOLVED
Closed: 10 years ago
Resolution: --- → INVALID
You need to log in before you can comment on or make changes to this bug.