Sendfile EAGAIN and FastCGI

Dave Hayes dave at jetcafe.org
Fri Jun 17 02:26:24 MSD 2011 

Hello. I'm using FreeBSD 7.4-RELEASE with Nginx 1.0.3 built from ports:

 # nginx -V
 nginx: nginx version: nginx/1.0.3
 nginx: TLS SNI support enabled
 nginx: configure arguments: --prefix=/usr/local/etc/nginx
 --with-cc-opt='-I /usr/local/include' --with-ld-opt='-L /usr/local/lib'
 --conf-path=/usr/local/etc/nginx/nginx.conf
 --sbin-path=/usr/local/sbin/nginx --pid-path=/var/run/nginx.pid
 --error-log-path=/var/log/nginx-error.log --user=www --group=www
 --with-debug --with-file-aio
 --http-client-body-temp-path=/var/tmp/nginx/client_body_temp
 --http-fastcgi-temp-path=/var/tmp/nginx/fastcgi_temp
 --http-proxy-temp-path=/var/tmp/nginx/proxy_temp
 --http-scgi-temp-path=/var/tmp/nginx/scgi_temp
 --http-uwsgi-temp-path=/var/tmp/nginx/uwsgi_temp
 --http-log-path=/var/log/nginx-access.log --with-http_gzip_static_module
 --with-http_realip_module --with-http_ssl_module
 --with-http_stub_status_module --with-http_sub_module --with-pcre

I'm also using FCGI to run a web application:

 # pkg_info | grep FCGI
 p5-FCGI-ProcManager-0.19 Functions for managing FastCGI applications
 p5-FCGI-Spawn-0.16.1 FastCGI server for CGI-like applications multiprocessing

It appears when I make a request larger than some value, the debug
output claims that sendfile() is returning EAGAIN, at which point the
request times out. Is this my misconfiguration, an nginx bug, an OS bug,
or something else I've not yet figured out? Debug output follows:

   2011/06/16 12:54:07 [debug] 51363#0: *1 http cl:21413 max:115343360
   2011/06/16 12:54:07 [debug] 51363#0: *1 rewrite phase: 3
   2011/06/16 12:54:07 [debug] 51363#0: *1 post rewrite phase: 4
   2011/06/16 12:54:07 [debug] 51363#0: *1 generic phase: 5
   2011/06/16 12:54:07 [debug] 51363#0: *1 generic phase: 6
   2011/06/16 12:54:07 [debug] 51363#0: *1 generic phase: 7
   2011/06/16 12:54:07 [debug] 51363#0: *1 access phase: 8
   2011/06/16 12:54:07 [debug] 51363#0: *1 access phase: 9
   2011/06/16 12:54:07 [debug] 51363#0: *1 post access phase: 10
   2011/06/16 12:54:07 [debug] 51363#0: *1 try files phase: 11
   2011/06/16 12:54:07 [debug] 51363#0: *1 posix_memalign: 
0000000801268000:4096 @16
   2011/06/16 12:54:07 [debug] 51363#0: *1 http client request body preread 
8118
   2011/06/16 12:54:07 [debug] 51363#0: *1 malloc: 0000000801269000:8192
   2011/06/16 12:54:07 [debug] 51363#0: *1 http read client request body
   2011/06/16 12:54:07 [debug] 51363#0: *1 SSL_read: 7177
   2011/06/16 12:54:07 [debug] 51363#0: *1 SSL_read: 1015
   2011/06/16 12:54:07 [debug] 51363#0: *1 http client request body recv 8192
   2011/06/16 12:54:07 [debug] 51363#0: *1 add cleanup: 0000000801268248
   2011/06/16 12:54:07 [debug] 51363#0: *1 hashed path: 
/var/tmp/nginx/client_body_temp/0000000001
   2011/06/16 12:54:07 [debug] 51363#0: *1 temp fd:34
   2011/06/16 12:54:07 [warn] 51363#0: *1 a client request body is buffered to 
a temporary file /var/tmp/nginx/client_body_temp/0000000001, client: 
205.147.26.121, server: wiki.dream-tech.com, request: "POST 
/bin/save/Some/File HTTP/1.1", host: "wiki.dream-tech.com", referrer: 
"https://mywiki.dream-tech.com/bin/edit/Some/File?t=1308252237;nowysiwyg=1"
   2011/06/16 12:54:07 [debug] 51363#0: *1 write: 34, 0000000801269000, 8192, 0
   2011/06/16 12:54:07 [debug] 51363#0: *1 SSL_read: 5103
   2011/06/16 12:54:07 [debug] 51363#0: *1 http client request body recv 5103
   2011/06/16 12:54:07 [debug] 51363#0: *1 http client request body rest 0
   2011/06/16 12:54:07 [debug] 51363#0: *1 write: 34, 0000000801269000, 5103, 
8192
   2011/06/16 12:54:07 [debug] 51363#0: *1 http init upstream, client timer: 0
   2011/06/16 12:54:07 [debug] 51363#0: *1 kevent set event: 33: ft:-2 fl:0025
   2011/06/16 12:54:07 [debug] 51363#0: *1 http script copy: "LOCATION_MATCH"
   2011/06/16 12:54:07 [debug] 51363#0: *1 http script copy: "bin"
   2011/06/16 12:54:07 [debug] 51363#0: *1 fastcgi param: "LOCATION_MATCH: bin"
   2011/06/16 12:54:07 [debug] 51363#0: *1 http script copy: "SCRIPT_FILENAME"
   2011/06/16 12:54:07 [debug] 51363#0: *1 http script copy: "/www/foswiki"
   2011/06/16 12:54:07 [debug] 51363#0: *1 http script var: "/bin/save"
   2011/06/16 12:54:07 [debug] 51363#0: *1 fastcgi param: "SCRIPT_FILENAME: 
/www/foswiki/bin/save"
   2011/06/16 12:54:07 [debug] 51363#0: *1 http script copy: "PATH_INFO"
   2011/06/16 12:54:07 [debug] 51363#0: *1 http script var: "/Some/File"
   2011/06/16 12:54:07 [debug] 51363#0: *1 fastcgi param: "PATH_INFO: 
/Some/File"
   2011/06/16 12:54:07 [debug] 51363#0: *1 http script copy: "SCRIPT_NAME"
   2011/06/16 12:54:07 [debug] 51363#0: *1 http script var: "/bin/save"
   2011/06/16 12:54:07 [debug] 51363#0: *1 fastcgi param: "SCRIPT_NAME: 
/bin/save"
   2011/06/16 12:54:07 [debug] 51363#0: *1 http script copy: "QUERY_STRING"
   2011/06/16 12:54:07 [debug] 51363#0: *1 fastcgi param: "QUERY_STRING: "
   2011/06/16 12:54:07 [debug] 51363#0: *1 http script copy: "REQUEST_METHOD"
   2011/06/16 12:54:07 [debug] 51363#0: *1 http script var: "POST"
   2011/06/16 12:54:07 [debug] 51363#0: *1 fastcgi param: "REQUEST_METHOD: 
POST"
   2011/06/16 12:54:07 [debug] 51363#0: *1 http script copy: "CONTENT_TYPE"
   2011/06/16 12:54:07 [debug] 51363#0: *1 http script var: 
"application/x-www-form-urlencoded"
   2011/06/16 12:54:07 [debug] 51363#0: *1 fastcgi param: "CONTENT_TYPE: 
application/x-www-form-urlencoded"
   2011/06/16 12:54:07 [debug] 51363#0: *1 http script copy: "CONTENT_LENGTH"
   2011/06/16 12:54:07 [debug] 51363#0: *1 http script var: "21413"
   2011/06/16 12:54:07 [debug] 51363#0: *1 fastcgi param: "CONTENT_LENGTH: 
21413"
   2011/06/16 12:54:07 [debug] 51363#0: *1 http script copy: "SCRIPT_NAME"
   2011/06/16 12:54:07 [debug] 51363#0: *1 http script var: "/bin/save"
   2011/06/16 12:54:07 [debug] 51363#0: *1 fastcgi param: "SCRIPT_NAME: 
/bin/save"
   2011/06/16 12:54:07 [debug] 51363#0: *1 http script copy: "REQUEST_URI"
   2011/06/16 12:54:07 [debug] 51363#0: *1 http script var: 
"/bin/save/Some/File"
   2011/06/16 12:54:07 [debug] 51363#0: *1 fastcgi param: "REQUEST_URI: 
/bin/save/Some/File"
   2011/06/16 12:54:07 [debug] 51363#0: *1 http script copy: "DOCUMENT_URI"
   2011/06/16 12:54:07 [debug] 51363#0: *1 http script var: 
"/bin/save/Some/File"
   2011/06/16 12:54:07 [debug] 51363#0: *1 fastcgi param: "DOCUMENT_URI: 
/bin/save/Some/File"
   2011/06/16 12:54:07 [debug] 51363#0: *1 http script copy: "DOCUMENT_ROOT"
   2011/06/16 12:54:07 [debug] 51363#0: *1 http script var: 
"/www/mywikis/mywiki.dream-tech.com"
   2011/06/16 12:54:07 [debug] 51363#0: *1 fastcgi param: "DOCUMENT_ROOT: 
/www/mywikis/mywiki.dream-tech.com"
   2011/06/16 12:54:07 [debug] 51363#0: *1 http script copy: "SERVER_PROTOCOL"
   2011/06/16 12:54:07 [debug] 51363#0: *1 http script var: "HTTP/1.1"
   2011/06/16 12:54:07 [debug] 51363#0: *1 fastcgi param: "SERVER_PROTOCOL: 
HTTP/1.1"
   2011/06/16 12:54:07 [debug] 51363#0: *1 http script copy: 
"GATEWAY_INTERFACE"
   2011/06/16 12:54:07 [debug] 51363#0: *1 http script copy: "CGI/1.1"
   2011/06/16 12:54:07 [debug] 51363#0: *1 fastcgi param: "GATEWAY_INTERFACE: 
CGI/1.1"
   2011/06/16 12:54:07 [debug] 51363#0: *1 http script copy: "SERVER_SOFTWARE"
   2011/06/16 12:54:07 [debug] 51363#0: *1 http script copy: "nginx/"
   2011/06/16 12:54:07 [debug] 51363#0: *1 http script var: "1.0.3"
   2011/06/16 12:54:07 [debug] 51363#0: *1 fastcgi param: "SERVER_SOFTWARE: 
nginx/1.0.3"
   2011/06/16 12:54:07 [debug] 51363#0: *1 http script copy: "REMOTE_ADDR"
   2011/06/16 12:54:07 [debug] 51363#0: *1 http script var: "205.147.26.121"
   2011/06/16 12:54:07 [debug] 51363#0: *1 fastcgi param: "REMOTE_ADDR: 
205.147.26.121"
   2011/06/16 12:54:07 [debug] 51363#0: *1 http script copy: "REMOTE_PORT"
   2011/06/16 12:54:07 [debug] 51363#0: *1 http script var: "52063"
   2011/06/16 12:54:07 [debug] 51363#0: *1 fastcgi param: "REMOTE_PORT: 52063"
   2011/06/16 12:54:07 [debug] 51363#0: *1 http script copy: "SERVER_ADDR"
   2011/06/16 12:54:07 [debug] 51363#0: *1 http script var: "205.147.26.122"
   2011/06/16 12:54:07 [debug] 51363#0: *1 fastcgi param: "SERVER_ADDR: 
205.147.26.122"
   2011/06/16 12:54:07 [debug] 51363#0: *1 http script copy: "SERVER_PORT"
   2011/06/16 12:54:07 [debug] 51363#0: *1 http script var: "443"
   2011/06/16 12:54:07 [debug] 51363#0: *1 fastcgi param: "SERVER_PORT: 443"
   2011/06/16 12:54:07 [debug] 51363#0: *1 http script copy: "SERVER_NAME"
   2011/06/16 12:54:07 [debug] 51363#0: *1 http script var: 
"wiki.dream-tech.com"
   2011/06/16 12:54:07 [debug] 51363#0: *1 fastcgi param: "SERVER_NAME: 
wiki.dream-tech.com"
   2011/06/16 12:54:07 [debug] 51363#0: *1 http script copy: "REDIRECT_STATUS"
   2011/06/16 12:54:07 [debug] 51363#0: *1 http script copy: "200"
   2011/06/16 12:54:07 [debug] 51363#0: *1 fastcgi param: "REDIRECT_STATUS: 
200"
   2011/06/16 12:54:07 [debug] 51363#0: *1 fastcgi param: "HTTP_HOST: 
wiki.dream-tech.com"
   2011/06/16 12:54:07 [debug] 51363#0: *1 fastcgi param: "HTTP_USER_AGENT: 
Mozilla/5.0 (Macintosh; Intel Mac OS X 10.5; rv:2.0.1) Gecko/20100101 
Firefox/4.0.1"
   2011/06/16 12:54:07 [debug] 51363#0: *1 fastcgi param: "HTTP_ACCEPT: 
text/html,application/xhtml+xml,application/xml;q=0.9,*/*;q=0.8"
   2011/06/16 12:54:07 [debug] 51363#0: *1 fastcgi param: 
"HTTP_ACCEPT_LANGUAGE: en-us,en;q=0.5"
   2011/06/16 12:54:07 [debug] 51363#0: *1 fastcgi param: 
"HTTP_ACCEPT_ENCODING: gzip, deflate"
   2011/06/16 12:54:07 [debug] 51363#0: *1 fastcgi param: 
"HTTP_ACCEPT_CHARSET: ISO-8859-1,utf-8;q=0.7,*;q=0.7"
   2011/06/16 12:54:07 [debug] 51363#0: *1 fastcgi param: "HTTP_KEEP_ALIVE: 
115"
   2011/06/16 12:54:07 [debug] 51363#0: *1 fastcgi param: "HTTP_DNT: 1"
   2011/06/16 12:54:07 [debug] 51363#0: *1 fastcgi param: "HTTP_CONNECTION: 
keep-alive"
   2011/06/16 12:54:07 [debug] 51363#0: *1 fastcgi param: "HTTP_REFERER: 
https://mywiki.dream-tech.com/bin/edit/Some/File?t=1308252237;nowysiwyg=1"
   2011/06/16 12:54:07 [debug] 51363#0: *1 fastcgi param: "HTTP_CONTENT_TYPE: 
application/x-www-form-urlencoded"
   2011/06/16 12:54:07 [debug] 51363#0: *1 fastcgi param: 
"HTTP_CONTENT_LENGTH: 21413"
   2011/06/16 12:54:07 [debug] 51363#0: *1 http cleanup add: 0000000801268BF8
   2011/06/16 12:54:07 [debug] 51363#0: *1 get rr peer, try: 1
   2011/06/16 12:54:07 [debug] 51363#0: *1 socket 35
   2011/06/16 12:54:07 [debug] 51363#0: *1 connect to 
unix:/var/tmp/sockets/foswiki, fd:35 #2
   2011/06/16 12:54:07 [debug] 51363#0: *1 kevent set event: 35: ft:-1 fl:0025
   2011/06/16 12:54:07 [debug] 51363#0: *1 connected
   2011/06/16 12:54:07 [debug] 51363#0: *1 http upstream connect: 0
   2011/06/16 12:54:07 [debug] 51363#0: *1 http upstream send request
   2011/06/16 12:54:07 [debug] 51363#0: *1 chain writer buf fl:0 s:1720
   2011/06/16 12:54:07 [debug] 51363#0: *1 chain writer buf fl:0 s:8118
   2011/06/16 12:54:07 [debug] 51363#0: *1 chain writer buf fl:0 s:10
   2011/06/16 12:54:07 [debug] 51363#0: *1 chain writer buf fl:0 s:13295
   2011/06/16 12:54:07 [debug] 51363#0: *1 chain writer buf fl:0 s:9
   2011/06/16 12:54:07 [debug] 51363#0: *1 chain writer in: 0000000801268C90
   2011/06/16 12:54:07 [debug] 51363#0: *1 sendfile() sent only 9848 bytes 
(35: Resource temporarily unavailable)
   2011/06/16 12:54:07 [debug] 51363#0: *1 sendfile: -1, @0 9848:13295
   2011/06/16 12:54:07 [debug] 51363#0: *1 chain writer out: 0000000801268CC0
   2011/06/16 12:54:07 [debug] 51363#0: *1 event timer add: 35: 
60000:1308254107181
   2011/06/16 12:54:07 [debug] 51363#0: *1 kevent set event: 35: ft:-2 fl:0025
   2011/06/16 12:54:07 [debug] 51363#0: *1 http finalize request: -4, 
"/bin/save/Some/File?" a:1, c:2
   2011/06/16 12:54:07 [debug] 51363#0: *1 http request count:2 blk:0
   2011/06/16 12:54:07 [debug] 51363#0: *1 post event 00000008012DE150
   2011/06/16 12:54:07 [debug] 51363#0: *1 delete posted event 00000008012DE150
   2011/06/16 12:54:07 [debug] 51363#0: *1 http run request: 
"/bin/save/Some/File?"
   2011/06/16 12:54:07 [debug] 51363#0: *1 http upstream check client, write 
event:1, "/bin/save/Some/File"
   2011/06/16 12:55:07 [debug] 51363#0: *1 event timer del: 35: 1308254107181
   2011/06/16 12:55:07 [debug] 51363#0: *1 http upstream request: 
"/bin/save/Some/File?"
   2011/06/16 12:55:07 [debug] 51363#0: *1 http upstream send request handler
   2011/06/16 12:55:07 [debug] 51363#0: *1 http next upstream, 4
   2011/06/16 12:55:07 [debug] 51363#0: *1 free rr peer 1 4
   2011/06/16 12:55:07 [error] 51363#0: *1 upstream timed out (60: Operation 
timed out) while sending request to upstream, client: 205.147.26.121, server: 
wiki.dream-tech.com, request: "POST /bin/save/Some/File HTTP/1.1", upstream: 
"fastcgi://unix:/var/tmp/sockets/foswiki:", host: "wiki.dream-tech.com", 
referrer: "https://mywiki.dream-tech.com/bin/edit/Some/File?t=1308252237;nowysi
wyg=1"

Thanks in advance for any insight that can be provided. :)
-- 
Dave Hayes - Consultant - Altadena CA, USA - dave at jetcafe.org 
>>> The opinions expressed above are entirely my own <<<

Do what you can, with what you have, where you are.

More information about the nginx mailing list