ESI Include Ordering and ESI Remote Fetch issues

[cd34]

Using: taf2-nginx-esi-0fe5af2
nginx_0.7.65

cat /etc/nginx/nginx.conf

user www-data;
worker_processes 1;

error_log /var/log/nginx/error.log;
pid /var/run/nginx.pid;

events {
worker_connections 1024;
debug_connection 192.168.24.68;
}

http {
include /etc/nginx/mime.types;

access_log  /var/log/nginx/access.log;

server {
listen 192.168.24.100:83;
server_name 192.168.24.100;
location / {
esi on;
root /var/www;
}
}
}

cat index.html

(index.html) This is the base document

results in the html emitted:

(esi/included.html) this is the server side include

(esi.html) this is a test ESI document

(index.html) This is the base document

So, it appears that the substitution is done but the content pasted to the top of the response header rather than the interior. You can see the empty lines where the <esi:include was removed.

Also, when using a URL rather than a local path, i.e. <esi:include src="http://192.168.24.100:83/esi.html" />

2010/04/17 11:54:53 [debug] 8029#0: *3 http filename: "/usr/local/nginx/htmlhttp://192.168.24.100:83/esi.html"
2010/04/17 11:54:53 [debug] 8029#0: *3 add cleanup: 00000000011904A0
2010/04/17 11:54:53 [error] 8029#0: *3 open() "/usr/local/nginx/htmlhttp://192.168.24.100:83/esi.html" failed (2: No such file or directory), client: 192.168.24.68, server: kvm, request: "GET / HTTP/1.1", subrequest: "http://192.168.24.100:83/esi.html", host: "192.168.24.100:83"

/usr/local/nginx/html is added prior to the url during the subrequest which causes it to fail.

detailed logs of that event:

detailed logs:

2010/04/17 11:54:53 [debug] 8029#0: 3 accept: 192.168.24.68 fd:3
2010/04/17 11:54:53 [debug] 8029#0: *3 event timer add: 3: 60000:1271519753316
2010/04/17 11:54:53 [debug] 8029#0: *3 epoll add event: fd:3 op:1 ev:80000001
2010/04/17 11:54:53 [debug] 8029#0: *3 malloc: 00000000011A30F0:1288
2010/04/17 11:54:53 [debug] 8029#0: *3 malloc: 0000000001188530:256
2010/04/17 11:54:53 [debug] 8029#0: *3 malloc: 00000000011A3600:1024
2010/04/17 11:54:53 [debug] 8029#0: *3 malloc: 000000000118E580:4096
2010/04/17 11:54:53 [debug] 8029#0: *3 http process request line
2010/04/17 11:54:53 [debug] 8029#0: *3 recv: fd:3 448 of 1024
2010/04/17 11:54:53 [debug] 8029#0: *3 http request line: "GET / HTTP/1.1"
2010/04/17 11:54:53 [debug] 8029#0: *3 http uri: "/"
2010/04/17 11:54:53 [debug] 8029#0: *3 http args: ""
2010/04/17 11:54:53 [debug] 8029#0: *3 http exten: ""
2010/04/17 11:54:53 [debug] 8029#0: *3 http process request header line
2010/04/17 11:54:53 [debug] 8029#0: *3 http header: "Host: 192.168.24.100:83"
2010/04/17 11:54:53 [debug] 8029#0: *3 http header: "Connection: keep-alive"
2010/04/17 11:54:53 [debug] 8029#0: *3 http header: "User-Agent: Mozilla/5.0 (Macintosh; U; Intel Mac OS X 10_6_3; en-US) AppleWebKit/533.2 (KHTML, like Gecko) Chrome/5.0.342.9 Safari/533.2"
2010/04/17 11:54:53 [debug] 8029#0: *3 http header: "Cache-Control: max-age=0"
2010/04/17 11:54:53 [debug] 8029#0: *3 http header: "Accept: application/xml,application/xhtml+xml,text/html;q=0.9,text/plain;q=0.8,image/png,/;q=0.5"
2010/04/17 11:54:53 [debug] 8029#0: *3 http header: "Accept-Encoding: gzip,deflate,sdch"
2010/04/17 11:54:53 [debug] 8029#0: *3 http header: "Accept-Language: en-US,en;q=0.8"
2010/04/17 11:54:53 [debug] 8029#0: *3 http header: "Accept-Charset: ISO-8859-1,utf-8;q=0.7,;q=0.3"
2010/04/17 11:54:53 [debug] 8029#0: *3 http header done
2010/04/17 11:54:53 [debug] 8029#0: *3 event timer del: 3: 1271519753316
2010/04/17 11:54:53 [debug] 8029#0: *3 generic phase: 0
2010/04/17 11:54:53 [debug] 8029#0: *3 add cleanup: 000000000118EF80
2010/04/17 11:54:53 [debug] 8029#0: *3 generic phase: 1
2010/04/17 11:54:53 [debug] 8029#0: *3 test location: "/"
2010/04/17 11:54:53 [debug] 8029#0: *3 using configuration "/"
2010/04/17 11:54:53 [debug] 8029#0: *3 http cl:-1 max:1048576
2010/04/17 11:54:53 [debug] 8029#0: *3 generic phase: 3
2010/04/17 11:54:53 [debug] 8029#0: *3 post rewrite phase: 4
2010/04/17 11:54:53 [debug] 8029#0: *3 generic phase: 5
2010/04/17 11:54:53 [debug] 8029#0: *3 add cleanup: 000000000118EFB8
2010/04/17 11:54:53 [debug] 8029#0: *3 generic phase: 6
2010/04/17 11:54:53 [debug] 8029#0: *3 generic phase: 7
2010/04/17 11:54:53 [debug] 8029#0: *3 access phase: 8
2010/04/17 11:54:53 [debug] 8029#0: *3 access phase: 9
2010/04/17 11:54:53 [debug] 8029#0: *3 post access phase: 10
2010/04/17 11:54:53 [debug] 8029#0: *3 content phase: 11
2010/04/17 11:54:53 [debug] 8029#0: *3 open index "/var/www/index.html"
2010/04/17 11:54:53 [debug] 8029#0: *3 internal redirect: "/index.html?"
2010/04/17 11:54:53 [debug] 8029#0: *3 generic phase: 1
2010/04/17 11:54:53 [debug] 8029#0: *3 test location: "/"
2010/04/17 11:54:53 [debug] 8029#0: *3 using configuration "/"
2010/04/17 11:54:53 [debug] 8029#0: *3 http cl:-1 max:1048576
2010/04/17 11:54:53 [debug] 8029#0: *3 generic phase: 3
2010/04/17 11:54:53 [debug] 8029#0: *3 post rewrite phase: 4
2010/04/17 11:54:53 [debug] 8029#0: *3 generic phase: 5
2010/04/17 11:54:53 [debug] 8029#0: *3 add cleanup: 000000000118F008
2010/04/17 11:54:53 [debug] 8029#0: *3 generic phase: 6
2010/04/17 11:54:53 [debug] 8029#0: *3 generic phase: 7
2010/04/17 11:54:53 [debug] 8029#0: *3 access phase: 8
2010/04/17 11:54:53 [debug] 8029#0: *3 access phase: 9
2010/04/17 11:54:53 [debug] 8029#0: *3 post access phase: 10
2010/04/17 11:54:53 [debug] 8029#0: *3 content phase: 11
2010/04/17 11:54:53 [debug] 8029#0: *3 content phase: 12
2010/04/17 11:54:53 [debug] 8029#0: *3 content phase: 13
2010/04/17 11:54:53 [debug] 8029#0: *3 content phase: 14
2010/04/17 11:54:53 [debug] 8029#0: *3 content phase: 15
2010/04/17 11:54:53 [debug] 8029#0: *3 http filename: "/var/www/index.html"
2010/04/17 11:54:53 [debug] 8029#0: *3 add cleanup: 000000000118F058
2010/04/17 11:54:53 [debug] 8029#0: *3 http static fd: 9
2010/04/17 11:54:53 [debug] 8029#0: *3 http set discard body
2010/04/17 11:54:53 [debug] 8029#0: *3 HTTP/1.1 200 OK
Server: nginx/0.7.65
Date: Sat, 17 Apr 2010 15:54:53 GMT
Content-Type: text/html
Transfer-Encoding: chunked
Connection: keep-alive

2010/04/17 11:54:53 [debug] 8029#0: *3 write new buf t:1 f:0 000000000118F238, pos 000000000118F238, size: 155 file: 0, size: 0
2010/04/17 11:54:53 [debug] 8029#0: *3 http write filter: l:0 f:0 s:155
2010/04/17 11:54:53 [debug] 8029#0: *3 http output filter "/index.html?"
2010/04/17 11:54:53 [debug] 8029#0: *3 copy filter: "/index.html?"
2010/04/17 11:54:53 [debug] 8029#0: *3 read: 9, 000000000118F3A8, 81, 0
2010/04/17 11:54:53 [debug] 8029#0: *3 malloc: 000000000118F9A0:4096
2010/04/17 11:54:53 [debug] 8029#0: *3 http subrequest "http://192.168.24.100:83/esi.html?"
2010/04/17 11:54:53 [debug] 8029#0: *3 http postpone filter "/index.html?" 000000000118F1D8
2010/04/17 11:54:53 [debug] 8029#0: *3 copy filter: 0 "/index.html?"
2010/04/17 11:54:53 [debug] 8029#0: *3 http finalize request: 0, "/index.html?" 0
2010/04/17 11:54:53 [debug] 8029#0: *3 event timer add: 3: 60000:1271519753316
2010/04/17 11:54:53 [debug] 8029#0: *3 http posted request: "http://192.168.24.100:83/esi.html?"
2010/04/17 11:54:53 [debug] 8029#0: *3 generic phase: 1
2010/04/17 11:54:53 [debug] 8029#0: *3 test location: "/"
2010/04/17 11:54:53 [debug] 8029#0: *3 using configuration ""
2010/04/17 11:54:53 [debug] 8029#0: *3 http cl:-1 max:1048576
2010/04/17 11:54:53 [debug] 8029#0: *3 generic phase: 3
2010/04/17 11:54:53 [debug] 8029#0: *3 post rewrite phase: 4
2010/04/17 11:54:53 [debug] 8029#0: *3 generic phase: 5
2010/04/17 11:54:53 [debug] 8029#0: *3 add cleanup: 0000000001190430
2010/04/17 11:54:53 [debug] 8029#0: *3 generic phase: 6
2010/04/17 11:54:53 [debug] 8029#0: *3 generic phase: 7
2010/04/17 11:54:53 [debug] 8029#0: *3 content phase: 11
2010/04/17 11:54:53 [debug] 8029#0: *3 content phase: 12
2010/04/17 11:54:53 [debug] 8029#0: *3 content phase: 13
2010/04/17 11:54:53 [debug] 8029#0: *3 content phase: 14
2010/04/17 11:54:53 [debug] 8029#0: *3 content phase: 15
2010/04/17 11:54:53 [debug] 8029#0: *3 http filename: "/usr/local/nginx/htmlhttp://192.168.24.100:83/esi.html"
2010/04/17 11:54:53 [debug] 8029#0: *3 add cleanup: 00000000011904A0
2010/04/17 11:54:53 [error] 8029#0: *3 open() "/usr/local/nginx/htmlhttp://192.168.24.100:83/esi.html" failed (2: No such file or directory), client: 192.168.24.68, server: kvm, request: "GET / HTTP/1.1", subrequest: "http://192.168.24.100:83/esi.html", host: "192.168.24.100:83"
2010/04/17 11:54:53 [debug] 8029#0: *3 http finalize request: 404, "http://192.168.24.100:83/esi.html?" 1
2010/04/17 11:54:53 [debug] 8029#0: *3 ssi stub output: "http://192.168.24.100:83/esi.html?"
2010/04/17 11:54:53 [debug] 8029#0: *3 http output filter "http://192.168.24.100:83/esi.html?"
2010/04/17 11:54:53 [debug] 8029#0: *3 copy filter: "http://192.168.24.100:83/esi.html?"
2010/04/17 11:54:53 [alert] 8029#0: *3 zero size buf in output t:0 r:0 f:0 0000000000000000 0000000000000000-0000000000000000 0000000000000000 0-0, client: 192.168.24.68, server: kvm, request: "GET / HTTP/1.1", subrequest: "http://192.168.24.100:83/esi.html", host: "192.168.24.100:83"
2010/04/17 11:54:53 [debug] 8029#0: *3 http postpone filter "http://192.168.24.100:83/esi.html?" 0000000000000000
2010/04/17 11:54:53 [debug] 8029#0: *3 copy filter: 0 "http://192.168.24.100:83/esi.html?"
2010/04/17 11:54:53 [debug] 8029#0: *3 http wake parent request: "/index.html?"
2010/04/17 11:54:53 [debug] 8029#0: *3 http posted request: "/index.html?"
2010/04/17 11:54:53 [debug] 8029#0: *3 http writer handler: "/index.html?"
2010/04/17 11:54:53 [debug] 8029#0: *3 http output filter "/index.html?"
2010/04/17 11:54:53 [debug] 8029#0: *3 copy filter: "/index.html?"
2010/04/17 11:54:53 [debug] 8029#0: *3 http postpone filter "/index.html?" 0000000000000000
2010/04/17 11:54:53 [debug] 8029#0: *3 http postpone filter output "/index.html?"
2010/04/17 11:54:53 [debug] 8029#0: *3 http chunk: 25
2010/04/17 11:54:53 [debug] 8029#0: *3 http chunk: 1
2010/04/17 11:54:53 [debug] 8029#0: *3 write old buf t:1 f:0 000000000118F238, pos 000000000118F238, size: 155 file: 0, size: 0
2010/04/17 11:54:53 [debug] 8029#0: *3 write new buf t:1 f:0 0000000000000000, pos 00000000011905C0, size: 4 file: 0, size: 0
2010/04/17 11:54:53 [debug] 8029#0: *3 write new buf t:1 f:0 000000000118F460, pos 000000000118F460, size: 25 file: 0, size: 0
2010/04/17 11:54:53 [debug] 8029#0: *3 write new buf t:1 f:0 000000000118F540, pos 000000000118F540, size: 1 file: 0, size: 0
2010/04/17 11:54:53 [debug] 8029#0: *3 write new buf t:0 f:0 0000000000000000, pos 0000000000483F48, size: 7 file: 0, size: 0
2010/04/17 11:54:53 [debug] 8029#0: *3 http write filter: l:1 f:0 s:192
2010/04/17 11:54:53 [debug] 8029#0: *3 http write filter limit 0
2010/04/17 11:54:53 [debug] 8029#0: *3 writev: 192
2010/04/17 11:54:53 [debug] 8029#0: *3 http write filter 0000000000000000
2010/04/17 11:54:53 [debug] 8029#0: *3 copy filter: 0 "/index.html?"
2010/04/17 11:54:53 [debug] 8029#0: *3 http writer output filter: 0, "/index.html?"
2010/04/17 11:54:53 [debug] 8029#0: *3 http writer done: "/index.html?"
2010/04/17 11:54:53 [debug] 8029#0: *3 http finalize request: 0, "/index.html?" 1
2010/04/17 11:54:53 [debug] 8029#0: *3 event timer del: 3: 1271519753316
2010/04/17 11:54:53 [debug] 8029#0: *3 set http keepalive handler
2010/04/17 11:54:53 [debug] 8029#0: *3 http close request
2010/04/17 11:54:53 [debug] 8029#0: *3 http log handler
2010/04/17 11:54:53 [debug] 8029#0: *3 run cleanup: 000000000118F058
2010/04/17 11:54:53 [debug] 8029#0: *3 file cleanup: fd:9
2010/04/17 11:54:53 [debug] 8029#0: *3 free: 000000000118E580, unused: 0
2010/04/17 11:54:53 [debug] 8029#0: *3 free: 000000000118F9A0, unused: 604
2010/04/17 11:54:53 [debug] 8029#0: *3 event timer add: 3: 75000:1271519768316
2010/04/17 11:54:53 [debug] 8029#0: *3 free: 00000000011A30F0
2010/04/17 11:54:53 [debug] 8029#0: *3 free: 00000000011A3600
2010/04/17 11:54:53 [debug] 8029#0: *3 hc free: 0000000000000000 0
2010/04/17 11:54:53 [debug] 8029#0: *3 hc busy: 0000000000000000 0
2010/04/17 11:54:53 [debug] 8029#0: *3 tcp_nodelay
2010/04/17 11:54:53 [debug] 8029#0: *3 post event 00000000011AD080
2010/04/17 11:54:53 [debug] 8029#0: *3 delete posted event 00000000011AD080
2010/04/17 11:54:53 [debug] 8029#0: *3 http keepalive handler
2010/04/17 11:54:53 [debug] 8029#0: *3 malloc: 00000000011A30F0:1024
2010/04/17 11:54:53 [debug] 8029#0: *3 recv: fd:3 -1 of 1024
2010/04/17 11:54:53 [debug] 8029#0: *3 recv() not ready (11: Resource temporarily unavailable)
2010/04/17 11:54:53 [debug] 8029#0: *3 http keepalive handler