Opened 7 years ago

Last modified 3 years ago

#217 accepted defect

Wrong "Content-Type" HTTP response header in certain configuration scenarios

Reported by: cschug.myopenid.com Owned by: somebody
Priority: minor Milestone:
Component: nginx-core Version: 1.3.x
Keywords: Content-Type regex location try_files alias Cc:
uname -a: Linux host.example.com 2.6.32-042stab055.12 #1 SMP Wed May 23 16:07:36 MSD 2012 i686 i686 i386 GNU/Linux
nginx -V: nginx version: nginx/1.3.6 TLS SNI support enabled configure arguments: --prefix=/usr/share/nginx --conf-path=/etc/nginx/nginx.conf --sbin-path=/usr/sbin/nginx --http-log-path=/var/log/nginx/access.log --error-log-path=/var/log/nginx/error.log --pid-path=/var/run/nginx.pid --user=nginx --group=nginx --with-openssl=openssl-1.0.1c --with-debug --with-http_stub_status_module --with-http_ssl_module --with-ipv6

Description

In certain configuration scenarios the "Content-Type" HTTP response header is not of the expected type but rather falls back to the default setting.

I was able to shrink down the configuration to a bare minimum test case which gives some indication that this might happen in conjunction with regex captured in "location", "try_files" and "alias" definitions.

Verfied with Nginx 1.3.6 (with patch.spdy-52.txt applied), but was also reproducible with earlier versions, see
http://mailman.nginx.org/pipermail/nginx/2012-August/034900.html
http://mailman.nginx.org/pipermail/nginx/2012-August/035170.html
(no response was given on those posts)

# nginx -V
nginx version: nginx/1.3.6
TLS SNI support enabled
configure arguments: --prefix=/usr/share/nginx --conf-path=/etc/nginx/nginx.conf --sbin-path=/usr/sbin/nginx --http-log-path=/var/log/nginx/access.log --error-log-path=/var/log/nginx/error.log --pid-path=/var/run/nginx.pid --user=nginx --group=nginx --with-openssl=openssl-1.0.1c --with-debug --with-http_stub_status_module --with-http_ssl_module --with-ipv6

Minimal test configuration for that specific scenario:

server {
    listen                          80;
    server_name                     t1.example.com;

    root                            /data/web/t1.example.com/htdoc;

    location                        ~ ^/quux(/.*)?$ {
        alias                       /data/web/t1.example.com/htdoc$1;
        try_files                   '' =404;
    }
}

First test request where Content-Type is being correctly set to "image/gif" as expected:

$ curl -s -o /dev/null -D - -H 'Host: t1.example.com' http://127.0.0.1/foo/bar.gif
HTTP/1.1 200 OK
Server: nginx/1.3.6
Date: Wed, 12 Sep 2012 14:20:09 GMT
Content-Type: image/gif
Content-Length: 68
Last-Modified: Thu, 02 Aug 2012 05:04:56 GMT
Connection: keep-alive
ETag: "501a0a78-44"
Accept-Ranges: bytes

Second test request where Content-Type is wrong, "application/octet-stream" instead of "image/gif" (actually matches the value of whatever "default_type" is set to):

$ curl -s -o /dev/null -D - -H 'Host: t1.example.com' http://127.0.0.1/quux/foo/bar.gif
HTTP/1.1 200 OK
Server: nginx/1.3.6
Date: Wed, 12 Sep 2012 14:20:14 GMT
Content-Type: application/octet-stream
Content-Length: 68
Last-Modified: Thu, 02 Aug 2012 05:04:56 GMT
Connection: keep-alive
ETag: "501a0a78-44"
Accept-Ranges: bytes

Debug log during the first test request:

2012/09/12 16:20:09 [debug] 15171#0: *1 delete posted event 09C2A710
2012/09/12 16:20:09 [debug] 15171#0: *1 malloc: 09BDA0C8:672
2012/09/12 16:20:09 [debug] 15171#0: *1 malloc: 09BE3210:1024
2012/09/12 16:20:09 [debug] 15171#0: *1 posix_memalign: 09C0AE10:4096 @16
2012/09/12 16:20:09 [debug] 15171#0: *1 http process request line
2012/09/12 16:20:09 [debug] 15171#0: *1 recv: fd:11 178 of 1024
2012/09/12 16:20:09 [debug] 15171#0: *1 http request line: "GET /foo/bar.gif HTTP/1.1"
2012/09/12 16:20:09 [debug] 15171#0: *1 http uri: "/foo/bar.gif"
2012/09/12 16:20:09 [debug] 15171#0: *1 http args: ""
2012/09/12 16:20:09 [debug] 15171#0: *1 http exten: "gif"
2012/09/12 16:20:09 [debug] 15171#0: *1 http process request header line
2012/09/12 16:20:09 [debug] 15171#0: *1 http header: "User-Agent: curl/7.19.7 (i386-redhat-linux-gnu) libcurl/7.19.7 NSS/3.13.1.0 zlib/1.2.3 libidn/1.18 libssh2/1.2.2"
2012/09/12 16:20:09 [debug] 15171#0: *1 http header: "Accept: */*"
2012/09/12 16:20:09 [debug] 15171#0: *1 http header: "Host: t1.example.com"
2012/09/12 16:20:09 [debug] 15171#0: *1 http header done
2012/09/12 16:20:09 [debug] 15171#0: *1 event timer del: 11: 3134905866
2012/09/12 16:20:09 [debug] 15171#0: *1 rewrite phase: 0
2012/09/12 16:20:09 [debug] 15171#0: *1 test location: ~ "^/quux(/.*)?$"
2012/09/12 16:20:09 [debug] 15171#0: *1 using configuration ""
2012/09/12 16:20:09 [debug] 15171#0: *1 http cl:-1 max:1048576
2012/09/12 16:20:09 [debug] 15171#0: *1 rewrite phase: 2
2012/09/12 16:20:09 [debug] 15171#0: *1 post rewrite phase: 3
2012/09/12 16:20:09 [debug] 15171#0: *1 generic phase: 4
2012/09/12 16:20:09 [debug] 15171#0: *1 generic phase: 5
2012/09/12 16:20:09 [debug] 15171#0: *1 access phase: 6
2012/09/12 16:20:09 [debug] 15171#0: *1 access phase: 7
2012/09/12 16:20:09 [debug] 15171#0: *1 post access phase: 8
2012/09/12 16:20:09 [debug] 15171#0: *1 try files phase: 9
2012/09/12 16:20:09 [debug] 15171#0: *1 content phase: 10
2012/09/12 16:20:09 [debug] 15171#0: *1 content phase: 11
2012/09/12 16:20:09 [debug] 15171#0: *1 content phase: 12
2012/09/12 16:20:09 [debug] 15171#0: *1 http filename: "/data/web/t1.example.com/htdoc/foo/bar.gif"
2012/09/12 16:20:09 [debug] 15171#0: *1 add cleanup: 09C0B3D8
2012/09/12 16:20:09 [debug] 15171#0: *1 http static fd: 14
2012/09/12 16:20:09 [debug] 15171#0: *1 http set discard body
2012/09/12 16:20:09 [debug] 15171#0: *1 HTTP/1.1 200 OK
Server: nginx/1.3.6
Date: Wed, 12 Sep 2012 14:20:09 GMT
Content-Type: image/gif
Content-Length: 68
Last-Modified: Thu, 02 Aug 2012 05:04:56 GMT
Connection: keep-alive
ETag: "501a0a78-44"
Accept-Ranges: bytes

2012/09/12 16:20:09 [debug] 15171#0: *1 write new buf t:1 f:0 09C0B500, pos 09C0B500, size: 235 file: 0, size: 0
2012/09/12 16:20:09 [debug] 15171#0: *1 http write filter: l:0 f:0 s:235
2012/09/12 16:20:09 [debug] 15171#0: *1 http output filter "/foo/bar.gif?"
2012/09/12 16:20:09 [debug] 15171#0: *1 http copy filter: "/foo/bar.gif?"
2012/09/12 16:20:09 [debug] 15171#0: *1 read: 14, 09C0B67C, 68, 0
2012/09/12 16:20:09 [debug] 15171#0: *1 http postpone filter "/foo/bar.gif?" 09C0B6C0
2012/09/12 16:20:09 [debug] 15171#0: *1 write old buf t:1 f:0 09C0B500, pos 09C0B500, size: 235 file: 0, size: 0
2012/09/12 16:20:09 [debug] 15171#0: *1 write new buf t:1 f:0 09C0B67C, pos 09C0B67C, size: 68 file: 0, size: 0
2012/09/12 16:20:09 [debug] 15171#0: *1 http write filter: l:1 f:0 s:303
2012/09/12 16:20:09 [debug] 15171#0: *1 http write filter limit 0
2012/09/12 16:20:09 [debug] 15171#0: *1 writev: 303
2012/09/12 16:20:09 [debug] 15171#0: *1 http write filter 00000000
2012/09/12 16:20:09 [debug] 15171#0: *1 http copy filter: 0 "/foo/bar.gif?"
2012/09/12 16:20:09 [debug] 15171#0: *1 http finalize request: 0, "/foo/bar.gif?" a:1, c:1
2012/09/12 16:20:09 [debug] 15171#0: *1 set http keepalive handler
2012/09/12 16:20:09 [debug] 15171#0: *1 http close request
2012/09/12 16:20:09 [debug] 15171#0: *1 http log handler
2012/09/12 16:20:09 [debug] 15171#0: *1 run cleanup: 09C0B3D8
2012/09/12 16:20:09 [debug] 15171#0: *1 file cleanup: fd:14
2012/09/12 16:20:09 [debug] 15171#0: *1 free: 09C0AE10, unused: 1645
2012/09/12 16:20:09 [debug] 15171#0: *1 event timer add: 11: 75000:3134920866
2012/09/12 16:20:09 [debug] 15171#0: *1 free: 09BDA0C8
2012/09/12 16:20:09 [debug] 15171#0: *1 free: 09BE3210
2012/09/12 16:20:09 [debug] 15171#0: *1 hc free: 00000000 0
2012/09/12 16:20:09 [debug] 15171#0: *1 hc busy: 00000000 0
2012/09/12 16:20:09 [debug] 15171#0: *1 tcp_nodelay
2012/09/12 16:20:09 [debug] 15171#0: *1 reusable connection: 1
2012/09/12 16:20:09 [debug] 15171#0: *1 post event 09C2A710
2012/09/12 16:20:09 [debug] 15171#0: posted event 09C2A710
2012/09/12 16:20:09 [debug] 15171#0: *1 delete posted event 09C2A710
2012/09/12 16:20:09 [debug] 15171#0: *1 http keepalive handler
2012/09/12 16:20:09 [debug] 15171#0: *1 malloc: 09BE3210:1024
2012/09/12 16:20:09 [debug] 15171#0: *1 recv: fd:11 -1 of 1024
2012/09/12 16:20:09 [debug] 15171#0: *1 recv() not ready (11: Resource temporarily unavailable)
2012/09/12 16:20:09 [debug] 15171#0: posted event 00000000
2012/09/12 16:20:09 [debug] 15171#0: worker cycle
2012/09/12 16:20:09 [debug] 15171#0: accept mutex locked
2012/09/12 16:20:09 [debug] 15171#0: epoll timer: 75000
2012/09/12 16:20:09 [debug] 15171#0: epoll: fd:11 ev:0001 d:09C117C8
2012/09/12 16:20:09 [debug] 15171#0: *1 post event 09C2A710
2012/09/12 16:20:09 [debug] 15171#0: timer delta: 2
2012/09/12 16:20:09 [debug] 15171#0: posted events 09C2A710
2012/09/12 16:20:09 [debug] 15171#0: posted event 09C2A710
2012/09/12 16:20:09 [debug] 15171#0: *1 delete posted event 09C2A710
2012/09/12 16:20:09 [debug] 15171#0: *1 http keepalive handler
2012/09/12 16:20:09 [debug] 15171#0: *1 recv: fd:11 0 of 1024
2012/09/12 16:20:09 [info] 15171#0: *1 client 127.0.0.1 closed keepalive connection
2012/09/12 16:20:09 [debug] 15171#0: *1 close http connection: 11
2012/09/12 16:20:09 [debug] 15171#0: *1 event timer del: 11: 3134920866
2012/09/12 16:20:09 [debug] 15171#0: *1 reusable connection: 0
2012/09/12 16:20:09 [debug] 15171#0: *1 free: 09BE3210
2012/09/12 16:20:09 [debug] 15171#0: *1 free: 00000000
2012/09/12 16:20:09 [debug] 15171#0: *1 free: 09BD9FC0, unused: 56

Debug log during the second test request:

2012/09/12 16:20:14 [debug] 15171#0: *2 delete posted event 09C2A710
2012/09/12 16:20:14 [debug] 15171#0: *2 malloc: 09BDA0C8:672
2012/09/12 16:20:14 [debug] 15171#0: *2 malloc: 09BE3210:1024
2012/09/12 16:20:14 [debug] 15171#0: *2 posix_memalign: 09C0AE10:4096 @16
2012/09/12 16:20:14 [debug] 15171#0: *2 http process request line
2012/09/12 16:20:14 [debug] 15171#0: *2 recv: fd:11 183 of 1024
2012/09/12 16:20:14 [debug] 15171#0: *2 http request line: "GET /quux/foo/bar.gif HTTP/1.1"
2012/09/12 16:20:14 [debug] 15171#0: *2 http uri: "/quux/foo/bar.gif"
2012/09/12 16:20:14 [debug] 15171#0: *2 http args: ""
2012/09/12 16:20:14 [debug] 15171#0: *2 http exten: "gif"
2012/09/12 16:20:14 [debug] 15171#0: *2 http process request header line
2012/09/12 16:20:14 [debug] 15171#0: *2 http header: "User-Agent: curl/7.19.7 (i386-redhat-linux-gnu) libcurl/7.19.7 NSS/3.13.1.0 zlib/1.2.3 libidn/1.18 libssh2/1.2.2"
2012/09/12 16:20:14 [debug] 15171#0: *2 http header: "Accept: */*"
2012/09/12 16:20:14 [debug] 15171#0: *2 http header: "Host: t1.example.com"
2012/09/12 16:20:14 [debug] 15171#0: *2 http header done
2012/09/12 16:20:14 [debug] 15171#0: *2 event timer del: 11: 3134910906
2012/09/12 16:20:14 [debug] 15171#0: *2 rewrite phase: 0
2012/09/12 16:20:14 [debug] 15171#0: *2 test location: ~ "^/quux(/.*)?$"
2012/09/12 16:20:14 [debug] 15171#0: *2 using configuration "^/quux(/.*)?$"
2012/09/12 16:20:14 [debug] 15171#0: *2 http cl:-1 max:1048576
2012/09/12 16:20:14 [debug] 15171#0: *2 rewrite phase: 2
2012/09/12 16:20:14 [debug] 15171#0: *2 post rewrite phase: 3
2012/09/12 16:20:14 [debug] 15171#0: *2 generic phase: 4
2012/09/12 16:20:14 [debug] 15171#0: *2 generic phase: 5
2012/09/12 16:20:14 [debug] 15171#0: *2 access phase: 6
2012/09/12 16:20:14 [debug] 15171#0: *2 access phase: 7
2012/09/12 16:20:14 [debug] 15171#0: *2 post access phase: 8
2012/09/12 16:20:14 [debug] 15171#0: *2 try files phase: 9
2012/09/12 16:20:14 [debug] 15171#0: *2 http script copy: "/data/web/t1.example.com/htdoc"
2012/09/12 16:20:14 [debug] 15171#0: *2 http script capture: "/foo/bar.gif"
2012/09/12 16:20:14 [debug] 15171#0: *2 trying to use file: "" "/data/web/t1.example.com/htdoc/foo/bar.gif"
2012/09/12 16:20:14 [debug] 15171#0: *2 try file uri: ""
2012/09/12 16:20:14 [debug] 15171#0: *2 content phase: 10
2012/09/12 16:20:14 [debug] 15171#0: *2 content phase: 11
2012/09/12 16:20:14 [debug] 15171#0: *2 content phase: 12
2012/09/12 16:20:14 [debug] 15171#0: *2 http script copy: "/data/web/t1.example.com/htdoc"
2012/09/12 16:20:14 [debug] 15171#0: *2 http script capture: "/foo/bar.gif"
2012/09/12 16:20:14 [debug] 15171#0: *2 http filename: "/data/web/t1.example.com/htdoc/foo/bar.gif"
2012/09/12 16:20:14 [debug] 15171#0: *2 add cleanup: 09C0B414
2012/09/12 16:20:14 [debug] 15171#0: *2 http static fd: 14
2012/09/12 16:20:14 [debug] 15171#0: *2 http set discard body
2012/09/12 16:20:14 [debug] 15171#0: *2 HTTP/1.1 200 OK
Server: nginx/1.3.6
Date: Wed, 12 Sep 2012 14:20:14 GMT
Content-Type: application/octet-stream
Content-Length: 68
Last-Modified: Thu, 02 Aug 2012 05:04:56 GMT
Connection: keep-alive
ETag: "501a0a78-44"
Accept-Ranges: bytes

2012/09/12 16:20:14 [debug] 15171#0: *2 write new buf t:1 f:0 09C0B53C, pos 09C0B53C, size: 250 file: 0, size: 0
2012/09/12 16:20:14 [debug] 15171#0: *2 http write filter: l:0 f:0 s:250
2012/09/12 16:20:14 [debug] 15171#0: *2 http output filter "?"
2012/09/12 16:20:14 [debug] 15171#0: *2 http copy filter: "?"
2012/09/12 16:20:14 [debug] 15171#0: *2 read: 14, 09C0B6C4, 68, 0
2012/09/12 16:20:14 [debug] 15171#0: *2 http postpone filter "?" 09C0B708
2012/09/12 16:20:14 [debug] 15171#0: *2 write old buf t:1 f:0 09C0B53C, pos 09C0B53C, size: 250 file: 0, size: 0
2012/09/12 16:20:14 [debug] 15171#0: *2 write new buf t:1 f:0 09C0B6C4, pos 09C0B6C4, size: 68 file: 0, size: 0
2012/09/12 16:20:14 [debug] 15171#0: *2 http write filter: l:1 f:0 s:318
2012/09/12 16:20:14 [debug] 15171#0: *2 http write filter limit 0
2012/09/12 16:20:14 [debug] 15171#0: *2 writev: 318
2012/09/12 16:20:14 [debug] 15171#0: *2 http write filter 00000000
2012/09/12 16:20:14 [debug] 15171#0: *2 http copy filter: 0 "?"
2012/09/12 16:20:14 [debug] 15171#0: *2 http finalize request: 0, "?" a:1, c:1
2012/09/12 16:20:14 [debug] 15171#0: *2 set http keepalive handler
2012/09/12 16:20:14 [debug] 15171#0: *2 http close request
2012/09/12 16:20:14 [debug] 15171#0: *2 http log handler
2012/09/12 16:20:14 [debug] 15171#0: *2 run cleanup: 09C0B414
2012/09/12 16:20:14 [debug] 15171#0: *2 file cleanup: fd:14
2012/09/12 16:20:14 [debug] 15171#0: *2 free: 09C0AE10, unused: 1568
2012/09/12 16:20:14 [debug] 15171#0: *2 event timer add: 11: 75000:3134925906
2012/09/12 16:20:14 [debug] 15171#0: *2 free: 09BDA0C8
2012/09/12 16:20:14 [debug] 15171#0: *2 free: 09BE3210
2012/09/12 16:20:14 [debug] 15171#0: *2 hc free: 00000000 0
2012/09/12 16:20:14 [debug] 15171#0: *2 hc busy: 00000000 0
2012/09/12 16:20:14 [debug] 15171#0: *2 tcp_nodelay
2012/09/12 16:20:14 [debug] 15171#0: *2 reusable connection: 1
2012/09/12 16:20:14 [debug] 15171#0: *2 post event 09C2A710
2012/09/12 16:20:14 [debug] 15171#0: posted event 09C2A710
2012/09/12 16:20:14 [debug] 15171#0: *2 delete posted event 09C2A710
2012/09/12 16:20:14 [debug] 15171#0: *2 http keepalive handler
2012/09/12 16:20:14 [debug] 15171#0: *2 malloc: 09BE3210:1024
2012/09/12 16:20:14 [debug] 15171#0: *2 recv: fd:11 -1 of 1024
2012/09/12 16:20:14 [debug] 15171#0: *2 recv() not ready (11: Resource temporarily unavailable)
2012/09/12 16:20:14 [debug] 15171#0: posted event 00000000
2012/09/12 16:20:14 [debug] 15171#0: worker cycle
2012/09/12 16:20:14 [debug] 15171#0: accept mutex locked
2012/09/12 16:20:14 [debug] 15171#0: epoll timer: 75000
2012/09/12 16:20:14 [debug] 15171#0: epoll: fd:11 ev:0001 d:09C117C9
2012/09/12 16:20:14 [debug] 15171#0: *2 post event 09C2A710
2012/09/12 16:20:14 [debug] 15171#0: timer delta: 2
2012/09/12 16:20:14 [debug] 15171#0: posted events 09C2A710
2012/09/12 16:20:14 [debug] 15171#0: posted event 09C2A710
2012/09/12 16:20:14 [debug] 15171#0: *2 delete posted event 09C2A710
2012/09/12 16:20:14 [debug] 15171#0: *2 http keepalive handler
2012/09/12 16:20:14 [debug] 15171#0: *2 recv: fd:11 0 of 1024
2012/09/12 16:20:14 [info] 15171#0: *2 client 127.0.0.1 closed keepalive connection
2012/09/12 16:20:14 [debug] 15171#0: *2 close http connection: 11
2012/09/12 16:20:14 [debug] 15171#0: *2 event timer del: 11: 3134925906
2012/09/12 16:20:14 [debug] 15171#0: *2 reusable connection: 0
2012/09/12 16:20:14 [debug] 15171#0: *2 free: 09BE3210
2012/09/12 16:20:14 [debug] 15171#0: *2 free: 00000000
2012/09/12 16:20:14 [debug] 15171#0: *2 free: 09BD9FC0, unused: 56

Change History (3)

comment:1 Changed 6 years ago by cschug.myopenid.com

No change in behavior with Nginx 1.3.7.

comment:2 Changed 6 years ago by mdounin

Yep, this looks like another case of try_files and alias problems, as collected in ticket #97.

comment:3 Changed 4 years ago by mdounin

  • sensitive set to 0
  • Status changed from new to accepted
Note: See TracTickets for help on using tickets.