Bug 831589

Summary: httpd with mod_nss returns Bad Request
Product: [Fedora] Fedora Reporter: Martin Kosek <mkosek>
Component: mod_nssAssignee: Matthew Harmsen <mharmsen>
Status: CLOSED ERRATA QA Contact: Fedora Extras Quality Assurance <extras-qa>
Severity: high Docs Contact:
Priority: unspecified    
Version: 17CC: mharmsen, nkinder, rcritten
Target Milestone: ---   
Target Release: ---   
Hardware: Unspecified   
OS: Unspecified   
Whiteboard:
Fixed In Version: Doc Type: Bug Fix
Doc Text:
Story Points: ---
Clone Of: Environment:
Last Closed: 2012-06-19 14:52:22 UTC Type: Bug
Regression: --- Mount Type: ---
Documentation: --- CRM:
Verified Versions: Category: ---
oVirt Team: --- RHEL 7.3 requirements from Atomic Host:
Cloudforms Team: --- Target Upstream Version:
Embargoed:
Attachments:
Description Flags
nss.conf
none
Server-Cert used for mod_nss
none
Configuration for mod_wsgi
none
Simple WSGI script used for reproduction
none
httpd error_log none

Description Martin Kosek 2012-06-13 11:33:31 UTC 
Description of problem:
When I configure httpd with mod_wsgi+mod_nss, httpd _sometimes_ returns "400 Bad Request" to legitimate requests sent to the secured index page:

-----------------------------
Bad Request

Your browser sent a request that this server could not understand.
Request header field is missing ':' separator.

86_64;
-----------------------------


Output from Firefox firebug:

Request Headers
Accept	text/html,application/xhtml+xml,application/xml;q=0.9,*/*;q=0.8
Accept-Encoding	gzip, deflate
Accept-Language	es,en-us;q=0.7,en;q=0.3
Cache-Control	max-age=0
Connection	keep-alive
Host	vm-131.idm.lab.bos.redhat.com
User-Agent	Mozilla/5.0 (X11; Linux x86_64; rv:13.0) Gecko/20100101 Firefox/13.0

Response Headers
Connection	close
Content-Length	394
Content-Type	text/html; charset=iso-8859-1
Date	Wed, 13 Jun 2012 11:21:51 GMT
Server	Apache/2.2.22 (Fedora)

Response body:
<!DOCTYPE HTML PUBLIC "-//IETF//DTD HTML 2.0//EN">
<html><head>
<title>400 Bad Request</title>
</head><body>
<h1>Bad Request</h1>
<p>Your browser sent a request that this server could not understand.<br />
Request header field is missing ':' separator.<br />
<pre>
86_64;</pre>
</p>
<hr>
<address>Apache/2.2.22 (Fedora) Server at vm-131.idm.lab.bos.redhat.com Port 443</address>
</body></html>


It seems to me that httpd gets to this state right after I "service httpd reload" it.

Version-Release number of selected component (if applicable):
httpd-2.2.22-4.fc17.x86_64
mod_nss-1.0.8-16.fc17.x86_64
mod_wsgi-3.3-2.fc17.x86_64

How reproducible:

Steps to Reproduce:
1. Install httpd, mod_nss, mod_wsgi
2. Generate Server-Cert in /etc/httpd/alias
3. Set up a WSGI script (you can use the one I attached)
4) Restart/reload apache and try several requests
  
Actual results:
httpd returns Bad Request for some requests

Expected results:
httpd always returns requested page
Comment 1 Martin Kosek 2012-06-13 11:35:57 UTC 
Created attachment 591446 [details]
nss.conf
Comment 2 Martin Kosek 2012-06-13 11:36:51 UTC 
Created attachment 591449 [details]
Server-Cert used for mod_nss
Comment 3 Martin Kosek 2012-06-13 11:37:32 UTC 
Created attachment 591450 [details]
Configuration for mod_wsgi
Comment 4 Martin Kosek 2012-06-13 11:38:09 UTC 
Created attachment 591451 [details]
Simple WSGI script used for reproduction
Comment 5 Martin Kosek 2012-06-13 11:42:49 UTC 
Created attachment 591453 [details]
httpd error_log
Comment 6 Martin Kosek 2012-06-13 12:02:21 UTC 
I tested the failing httpd with another SSL provider (mod_ssl) and this issue did not occur, i.e. I really think this must be in mod_nss.
Comment 7 Martin Kosek 2012-06-15 07:23:59 UTC 
I used httpd's dumpio module to track what is being sent to apache from SSL filter and it is indeed wrong:


[Fri Jun 15 03:18:02 2012] [info] Connection to child 0 established (server vm-091.idm.lab.bos.redhat.com:443, client 10.16.78.91)
[Fri Jun 15 03:18:02 2012] [debug] mod_dumpio.c(113): mod_dumpio: dumpio_in [getline-blocking] 0 readbytes
[Fri Jun 15 03:18:02 2012] [debug] mod_dumpio.c(55): mod_dumpio:  dumpio_in (data-TRANSIENT): 32 bytes
[Fri Jun 15 03:18:02 2012] [debug] mod_dumpio.c(74): mod_dumpio:  dumpio_in (data-TRANSIENT): POST /ipa/session/xml HTTP/1.1\r\n
[Fri Jun 15 03:18:02 2012] [debug] mod_dumpio.c(113): mod_dumpio: dumpio_in [getline-blocking] 0 readbytes
[Fri Jun 15 03:18:02 2012] [debug] mod_dumpio.c(55): mod_dumpio:  dumpio_in (data-TRANSIENT): 37 bytes
[Fri Jun 15 03:18:02 2012] [debug] mod_dumpio.c(74): mod_dumpio:  dumpio_in (data-TRANSIENT): Host: vm-091.idm.lab.bos.redhat.com\r\n
[Fri Jun 15 03:18:02 2012] [debug] mod_dumpio.c(113): mod_dumpio: dumpio_in [getline-blocking] 0 readbytes
[Fri Jun 15 03:18:02 2012] [debug] mod_dumpio.c(55): mod_dumpio:  dumpio_in (data-TRANSIENT): 23 bytes
[Fri Jun 15 03:18:02 2012] [debug] mod_dumpio.c(74): mod_dumpio:  dumpio_in (data-TRANSIENT): Accept-Encoding: gzip\r\n
[Fri Jun 15 03:18:02 2012] [debug] mod_dumpio.c(113): mod_dumpio: dumpio_in [getline-blocking] 0 readbytes
[Fri Jun 15 03:18:02 2012] [debug] mod_dumpio.c(55): mod_dumpio:  dumpio_in (data-TRANSIENT): 24 bytes
[Fri Jun 15 03:18:02 2012] [debug] mod_dumpio.c(74): mod_dumpio:  dumpio_in (data-TRANSIENT): Accept-Language: en-us\r\n
[Fri Jun 15 03:18:02 2012] [debug] mod_dumpio.c(113): mod_dumpio: dumpio_in [getline-blocking] 0 readbytes
[Fri Jun 15 03:18:02 2012] [debug] mod_dumpio.c(55): mod_dumpio:  dumpio_in (data-TRANSIENT): 56 bytes
[Fri Jun 15 03:18:02 2012] [debug] mod_dumpio.c(74): mod_dumpio:  dumpio_in (data-TRANSIENT): Referer: https://vm-091.idm.lab.bos.redhat.com/ipa/   xml\r\n
[Fri Jun 15 03:18:02 2012] [debug] mod_dumpio.c(113): mod_dumpio: dumpio_in [getline-blocking] 0 readbytes
[Fri Jun 15 03:18:02 2012] [debug] mod_dumpio.c(55): mod_dumpio:  dumpio_in (data-TRANSIENT): 83 bytes
[Fri Jun 15 03:18:02 2012] [debug] mod_dumpio.c(74): mod_dumpio:  dumpio_in (data-TRANSIENT): Cookie: ipa_session=951ed824da5dbaaae008c129c41fd969; httponly; Path=/ipa; secure\r\n
[Fri Jun 15 03:18:02 2012] [debug] mod_dumpio.c(113): mod_dumpio: dumpio_in [getline-blocking] 0 readbytes
[Fri Jun 15 03:18:02 2012] [debug] mod_dumpio.c(55): mod_dumpio:  dumpio_in (data-TRANSIENT): 28 bytes
[Fri Jun 15 03:18:02 2012] [debug] mod_dumpio.c(74): mod_dumpio:  dumpio_in (data-TRANSIENT): boolean>0</boolean></value>\n
[Fri Jun 15 03:18:02 2012] [debug] mod_dumpio.c(113): mod_dumpio: dumpio_in [getline-blocking] 0 readbytes
[Fri Jun 15 03:18:02 2012] [debug] mod_dumpio.c(55): mod_dumpio:  dumpio_in (data-TRANSIENT): 10 bytes
[Fri Jun 15 03:18:02 2012] [debug] mod_dumpio.c(74): mod_dumpio:  dumpio_in (data-TRANSIENT): </member>\n
[Fri Jun 15 03:18:02 2012] [debug] protocol.c(800): [client 10.16.78.91] Request header field is missing ':' separator: boolean>0</boolean></       value>, referer: https://vm-091.idm.lab.bos.redhat.com/ipa/xml

It seems that some data are missing - it returned:
(data-TRANSIENT): Cookie: ipa_session=951ed824da5dbaaae008c129c41fd969; httponly; Path=/ipa; secure\r\n

And then it missed some data and returned:
(data-TRANSIENT): boolean>0</boolean></value>\n
Comment 8 Fedora Update System 2012-06-15 15:44:46 UTC 
mod_nss-1.0.8-17.fc17 has been submitted as an update for Fedora 17.
https://admin.fedoraproject.org/updates/mod_nss-1.0.8-17.fc17
Comment 9 Fedora Update System 2012-06-15 23:54:53 UTC 
Package mod_nss-1.0.8-17.fc17:
* should fix your issue,
* was pushed to the Fedora 17 testing repository,
* should be available at your local mirror within two days.
Update it with:
# su -c 'yum update --enablerepo=updates-testing mod_nss-1.0.8-17.fc17'
as soon as you are able to.
Please go to the following url:
https://admin.fedoraproject.org/updates/FEDORA-2012-9514/mod_nss-1.0.8-17.fc17
then log in and leave karma (feedback).
Comment 10 Fedora Update System 2012-06-19 14:52:22 UTC 
mod_nss-1.0.8-17.fc17 has been pushed to the Fedora 17 stable repository.  If problems still persist, please make note of it in this bug report.