nginx-shib / nginx-http-shibboleth

Shibboleth auth request module for nginx
https://github.com/nginx-shib/nginx-http-shibboleth/wiki
Other
209 stars 27 forks source link

Shibauthorizer 403 responses are Gzipped & missing Content-Encoding headers #8

Closed vidiecan closed 8 years ago

vidiecan commented 8 years ago

We have stumbled on two issues using shibboleth sp 2.5.3 with fastcgi and nginx 1.8.0. The first issue is that the shibauthoriser does not use redirectErrors from shibboleth2.xml and the second is that the response from shibauthorizer contains content type (type/html) but the gzip filter is applied anyway.

Our setup shibboleth2.xml

 14     <RequestMapper type="XML">           
 15       <RequestMap>                       
 16         <Host name="..."  
 17               authType="shibboleth"      
 18               requireSession="true"      
 19               redirectToSSL="443">       
...
 28           <Path name="dev">
 29             <Path name="munin">
 30                 <AccessControl>
 31                     <Rule require="affiliation">staff@uni</Rule>
 32                 </AccessControl>
 33             </Path>
 34           </Path>
...
 92         <Errors supportContact="..."                        
 93             redirectErrors="https://url"/> 

For the record, "standard" nginx sites-enabled:

154   location /dev/munin/ {
155     shib_request /shibauthorizer;
156     alias /var/cache/munin/www/;
...
199   location = /shibauthorizer {
200     internal;
201     include fastcgi_params;
202     fastcgi_pass unix:/opt/shibboleth-sp-fastcgi/shibauthorizer.sock;
203   }

Standard nginx.conf gzip

 48   gzip on;                                           
...
 52   gzip_types    text/plain text/css                  
 53                 application/x-javascript text/xml    
 54                 application/xml application/xml+rss  
...

Nginx error log

 83417 2015/09/22 12:43:04 [debug] 16858#0: *18 epoll add connection: fd:17 ev:80002005                                
 83418 2015/09/22 12:43:04 [debug] 16858#0: *18 connect to unix:/opt/shibboleth-sp-fastcgi/shibauthorizer.sock, fd:17 #
 83419 2015/09/22 12:43:04 [debug] 16858#0: *18 connected                                                              
 83420 2015/09/22 12:43:04 [debug] 16858#0: *18 http upstream connect: 0                                               
 83421 2015/09/22 12:43:04 [debug] 16858#0: *18 posix_memalign: 0000000002886D90:128 @16                               
 83422 2015/09/22 12:43:04 [debug] 16858#0: *18 http upstream send request                                             
 83423 2015/09/22 12:43:04 [debug] 16858#0: *18 http upstream send request body                                        
 83424 2015/09/22 12:43:04 [debug] 16858#0: *18 chain writer buf fl:0 s:1672                                           
 83425 2015/09/22 12:43:04 [debug] 16858#0: *18 chain writer in: 000000000288A040                                      
 83426 2015/09/22 12:43:04 [debug] 16858#0: *18 writev: 1672 of 1672                                                   
 83427 2015/09/22 12:43:04 [debug] 16858#0: *18 chain writer out: 0000000000000000                                     
 83428 2015/09/22 12:43:04 [debug] 16858#0: *18 event timer add: 17: 60000:1442918644499                               
 83429 2015/09/22 12:43:04 [debug] 16858#0: *18 http finalize request: -4, "/shibauthorizer?" a:1, c:3                 
 83430 2015/09/22 12:43:04 [debug] 16858#0: *18 http request count:3 blk:0                                             
 83431 2015/09/22 12:43:04 [debug] 16858#0: *18 post event 000000000291C6D0                                            
 83432 2015/09/22 12:43:04 [debug] 16858#0: *18 post event 000000000291C600                                            
 83433 2015/09/22 12:43:04 [debug] 16858#0: *18 delete posted event 000000000291C6D0                                   
 83434 2015/09/22 12:43:04 [debug] 16858#0: *18 http run request: "/shibauthorizer?"                                   
 83435 2015/09/22 12:43:04 [debug] 16858#0: *18 http upstream check client, write event:1, "/shibauthorizer"           
 83436 2015/09/22 12:43:04 [debug] 16858#0: *18 http upstream recv(): -1 (11: Resource temporarily unavailable)        
 83437 2015/09/22 12:43:04 [debug] 16858#0: *18 delete posted event 000000000291C600                                   
 83438 2015/09/22 12:43:04 [debug] 16858#0: *18 http upstream request: "/shibauthorizer?"                              
 83439 2015/09/22 12:43:04 [debug] 16858#0: *18 http upstream dummy handler                                            
 83440 2015/09/22 12:43:04 [debug] 16858#0: *18 post event 0000000002908DF0                                            
 83441 2015/09/22 12:43:04 [debug] 16858#0: *18 post event 000000000291C600                                            
 83442 2015/09/22 12:43:04 [debug] 16858#0: *18 delete posted event 0000000002908DF0                                   
 83443 2015/09/22 12:43:04 [debug] 16858#0: *18 http upstream request: "/shibauthorizer?"                              
 83444 2015/09/22 12:43:04 [debug] 16858#0: *18 http upstream process header                                           
 83445 2015/09/22 12:43:04 [debug] 16858#0: *18 malloc: 00000000028C08B0:4096                                          
 83446 2015/09/22 12:43:04 [debug] 16858#0: *18 recv: fd:17 208 of 4096                                                
 83447 2015/09/22 12:43:04 [debug] 16858#0: *18 http fastcgi record byte: 01                                           
 83448 2015/09/22 12:43:04 [debug] 16858#0: *18 http fastcgi record byte: 06                                           
 83449 2015/09/22 12:43:04 [debug] 16858#0: *18 http fastcgi record byte: 00                                           
 83450 2015/09/22 12:43:04 [debug] 16858#0: *18 http fastcgi record byte: 01                                           
 83451 2015/09/22 12:43:04 [debug] 16858#0: *18 http fastcgi record byte: 00                                           
 83452 2015/09/22 12:43:04 [debug] 16858#0: *18 http fastcgi record byte: AE                                           
 83453 2015/09/22 12:43:04 [debug] 16858#0: *18 http fastcgi record byte: 02                                           

 83455 2015/09/22 12:43:04 [debug] 16858#0: *18 http fastcgi record length: 174                                            
 83456 2015/09/22 12:43:04 [debug] 16858#0: *18 http fastcgi parser: 0                                                     
 83457 2015/09/22 12:43:04 [debug] 16858#0: *18 http fastcgi header: "Status: 403 Forbidden"                               
 83458 2015/09/22 12:43:04 [debug] 16858#0: *18 http fastcgi parser: 0                                                     
 83459 2015/09/22 12:43:04 [debug] 16858#0: *18 http fastcgi header: "Connection: close"                                   
 83460 2015/09/22 12:43:04 [debug] 16858#0: *18 http fastcgi parser: 0                                                     
 83461 2015/09/22 12:43:04 [debug] 16858#0: *18 http fastcgi header: "Cache-Control: private,no-store,no-cache,max-age=0"  
 83462 2015/09/22 12:43:04 [debug] 16858#0: *18 http fastcgi parser: 0                                                     
 83463 2015/09/22 12:43:04 [debug] 16858#0: *18 http fastcgi header: "Content-Type: text/html"                             
 83464 2015/09/22 12:43:04 [debug] 16858#0: *18 http fastcgi parser: 0                                                     
 83465 2015/09/22 12:43:04 [debug] 16858#0: *18 http fastcgi header: "Expires: Wed, 01 Jan 1997 12:00:00 GMT"              
 83466 2015/09/22 12:43:04 [debug] 16858#0: *18 http fastcgi parser: 1                                                     
 83467 2015/09/22 12:43:04 [debug] 16858#0: *18 http fastcgi header done                                                   
 83468 2015/09/22 12:43:04 [debug] 16858#0: *18 finalize http upstream request: 0                                          
 83469 2015/09/22 12:43:04 [debug] 16858#0: *18 finalize http fastcgi request                                              
 83470 2015/09/22 12:43:04 [debug] 16858#0: *18 free rr peer 1 0                                                           
 83471 2015/09/22 12:43:04 [debug] 16858#0: *18 close http upstream connection: 17                                         
 83472 2015/09/22 12:43:04 [debug] 16858#0: *18 free: 0000000002886D90, unused: 48                                         
 83473 2015/09/22 12:43:04 [debug] 16858#0: *18 event timer del: 17: 1442918644499                                         
 83474 2015/09/22 12:43:04 [debug] 16858#0: *18 delete posted event 000000000291C600                                       
 83475 2015/09/22 12:43:04 [debug] 16858#0: *18 reusable connection: 0                                                     
 83476 2015/09/22 12:43:04 [debug] 16858#0: *18 http finalize request: 0, "/shibauthorizer?" a:1, c:2                      
 83477 2015/09/22 12:43:04 [debug] 16858#0: *18 shib request done s:403                                                    
 83478 2015/09/22 12:43:04 [debug] 16858#0: *18 http wake parent request: "/dev/munin/?"                                   
 83479 2015/09/22 12:43:04 [debug] 16858#0: *18 http posted request: "/dev/munin/?"                                        
 83480 2015/09/22 12:43:04 [debug] 16858#0: *18 access phase: 7                                                            
 83481 2015/09/22 12:43:04 [debug] 16858#0: *18 shib request handler                                                       
 83482 2015/09/22 12:43:04 [debug] 16858#0: *18 shib request set variables                                                 
 83483 2015/09/22 12:43:04 [debug] 16858#0: *18 shib request authorizer handler                                            
 83484 2015/09/22 12:43:04 [debug] 16858#0: *18 shib request authorizer returning sub-response                             
 83485 2015/09/22 12:43:04 [debug] 16858#0: *18 http finalize request: 403, "/dev/munin/?" a:1, c:1                        
 83486 2015/09/22 12:43:04 [debug] 16858#0: *18 http special response: 403, "/dev/munin/?"                                 
 83487 2015/09/22 12:43:04 [debug] 16858#0: *18 http set discard body                                                      
 83488 2015/09/22 12:43:04 [debug] 16858#0: *18 posix_memalign: 000000000287A790:4096 @16                                  
 83489 2015/09/22 12:43:04 [debug] 16858#0: *18 HTTP/1.1 403 Forbidden^M                                                   
 83490 Server: nginx/1.8.0^M                                                                                               
 83491 Date: Tue, 22 Sep 2015 10:43:04 GMT^M                                                                               
 83492 Content-Type: text/html^M                                                                                           
 83493 Transfer-Encoding: chunked^M                                                                                        
 83497
 83498 2015/09/22 12:43:04 [debug] 16858#0: *18 write new buf t:1 f:0 000000000287A7B0, pos 000000000287A7B0, size: 253 file: 0, size: 0
 83499 2015/09/22 12:43:04 [debug] 16858#0: *18 http write filter: l:0 f:0 s:253
 83500 2015/09/22 12:43:04 [debug] 16858#0: *18 http output filter "/dev/munin/?"
 83501 2015/09/22 12:43:04 [debug] 16858#0: *18 http copy filter: "/dev/munin/?"
 83502 2015/09/22 12:43:04 [debug] 16858#0: *18 http postpone filter "/dev/munin/?" 000000000288A4B0
 83503 2015/09/22 12:43:04 [debug] 16858#0: *18 http gzip filter
 83504 2015/09/22 12:43:04 [debug] 16858#0: *18 malloc: 00000000028D6900:12288
 83505 2015/09/22 12:43:04 [debug] 16858#0: *18 gzip alloc: n:1 s:5928 a:8192 p:00000000028D6900

Browser got these http response headers

Cache-Control: private,no-store,no-cache,max-age=0
Connection: keep-alive
Content-Length: 168
Content-Type: text/html
Date: Tue, 22 Sep 2015 11:07:11 GMT
Expires: Wed, 01 Jan 1997 12:00:00 GMT
Server: nginx/1.8.0

and the actual response content is some garbage (gzipped stuff).

Setting gzip_min_length 1000; solves the second issue and returns

<html>
<head><title>403 Forbidden</title></head>
<body bgcolor="white">
<center><h1>403 Forbidden</h1></center>
<hr><center>nginx/1.8.0</center>
</body>
</html>

However, the expected output would be a redirect to the url specified in shibboleth2.xml.

davidjb commented 8 years ago

Thanks for the error report. The shibauthorizer looks to be behaving correctly as authorisation failures aren't considered errors by Shibboleth's SP and are returned as 403s. See the comment from Scott Cantor. If you're looking to show the user a custom 403 page, then Nginx's error_page will be what you're looking for.

If you do want to test/see the results of redirectErrors, try a request to something like /Shibboleth.sso/non-existent -- that redirects correctly for me with Shibboleth SP 2.5.5 and Nginx 1.8.0.

As for the latter issue about Gzipped content missing the Content-Encoding header (or being incorrect gzipped in the first place), I've reproduced this. This seems to also affect error_page output too -- eg error_page 403 =302 http://foobar.com is missing the Location header and calls to add_header aren't reflected in the response. The sub-request's headers are being returned to the client which is likely messing with Nginx's ability to change headers (Gzip, etc) just before they're returned.

I'll give this some more thought and see what I can come up with.

davidjb commented 8 years ago

The issue is that the subrequest response's headers are being returned to the client in such a way that other filters (eg Gzip) can't touch them. Hence, the body is gzipped but the Content-Encoding header is missing. I'm going to tidy up this issue in lieu of #9. @vidiecan, if you've got suggestions on that, go for it.

davidjb commented 8 years ago

@vidiecan All resolved via #9. Rebuild your Nginx with the latest changes from the repo and you'll get a generic Nginx 403 error page that's been correctly Gzipped on delivery. Now, you can use error_page 403 ... to configure a suitable page to show the user. I also added an example for this into the documentation whilst I was at it.

Thanks for the reporting the original issue!