Timeout when sending over 16k of data with UTF-8 characters

Server NGINX
1

I’m experiencing an issue where nginx and having a difficult time
determining the cause. It is timing out on an HTTPS PUT (to an HTTP
backend) when content length is greater than 16384 (per
$content_length) and it contains UTF-8 characters. The connection
hangs and I get a 408 returned by nginx after 60 seconds. When I make
the same call directly to the backend, it succeeds. Removing the UTF-8
characters or reducing the seize to 16384 or below will both allow the
request to succeed through nginx.

client_body_buffer_size is defaulting to 8k, and using
$request_body_file I’ve determined that it isn’t the use of a
temporary file triggering the error. Are there any other configuration
values that default to 16k?

My current nginx configuration:
nginx: nginx version: nginx/1.0.5
nginx: built by gcc 4.4.3 (Ubuntu 4.4.3-4ubuntu5)
nginx: TLS SNI support enabled
nginx: configure arguments: --conf-path=/etc/nginx
–prefix=/srv/nginx/1.0.5 --with-http_ssl_module
–with-http_stub_status_module --add-module=…/nginx-x-rid-header
–with-ld-opt=-luuid

I also tried 1.1.6 to see if its UTF-8 patch would help, to no avail:
nginx: nginx version: nginx/1.1.6
nginx: built by gcc 4.4.3 (Ubuntu 4.4.3-4ubuntu5)
nginx: TLS SNI support enabled
nginx: configure arguments: --conf-path=/etc/nginx
–prefix=/tmp/nginx-1.1.6 --with-http_ssl_module
–with-http_stub_status_module --add-module=…/nginx-x-rid-header
–with-ld-opt=-luuid

Successful PUT:

$status 200
$request_time 0.943
$body_bytes_sent 16384
$upstream_status 200
$upstream_response_time 0.216
$request_length 17330
$content_length 16384
$request_body_file /srv/nginx/1.0.5/client_body_temp/0000000249

Failing PUT:
$status 408
$request_time 60.911
$body_bytes_sent -
$upstream_status -
$upstream_response_time -
$request_length 17330
$content_length 16385
$request_body_file /srv/nginx/1.0.5/client_body_temp/0000000250

Ideas?
Bryan

2

On Tue, Nov 01, 2011 at 01:00:25AM -0400, Bryan McLellan wrote:

$request_body_file I’ve determined that it isn’t the use of a
–with-ld-opt=-luuid
Successful PUT:
Failing PUT:
Bryan
Could you create debug log:
A debugging log

What does this module do ?
–add-module=../nginx-x-rid-header

–
Igor S.

3

On Tue, Nov 1, 2011 at 2:21 AM, Igor S. [email protected] wrote:

Could you create debug log:
A debugging log

You

Ruby throws an EOFError when this occurs:

EOFError: end of file reached
from
/home/btm/.rvm/rubies/ruby-1.9.1-p431/lib/ruby/1.9.1/net/protocol.rb:135:in
sysread' from /home/btm/.rvm/rubies/ruby-1.9.1-p431/lib/ruby/1.9.1/net/protocol.rb:135:in block in rbuf_fill’
from
/home/btm/.rvm/rubies/ruby-1.9.1-p431/lib/ruby/1.9.1/timeout.rb:52:in
timeout' from /home/btm/.rvm/rubies/ruby-1.9.1-p431/lib/ruby/1.9.1/timeout.rb:82:in timeout’
from
/home/btm/.rvm/rubies/ruby-1.9.1-p431/lib/ruby/1.9.1/net/protocol.rb:134:in
rbuf_fill' from /home/btm/.rvm/rubies/ruby-1.9.1-p431/lib/ruby/1.9.1/net/protocol.rb:116:in readuntil’
from
/home/btm/.rvm/rubies/ruby-1.9.1-p431/lib/ruby/1.9.1/net/protocol.rb:126:in
readline' from /home/btm/.rvm/rubies/ruby-1.9.1-p431/lib/ruby/1.9.1/net/http.rb:2136:in read_status_line’
from
/home/btm/.rvm/rubies/ruby-1.9.1-p431/lib/ruby/1.9.1/net/http.rb:2125:in
read_new' from /home/btm/.rvm/rubies/ruby-1.9.1-p431/lib/ruby/1.9.1/net/http.rb:1117:in transport_request’
from
/home/btm/.rvm/rubies/ruby-1.9.1-p431/lib/ruby/1.9.1/net/http.rb:1103:in
request' from /home/btm/.rvm/rubies/ruby-1.9.1-p431/lib/ruby/1.9.1/net/http.rb:1096:in block in request’
from
/home/btm/.rvm/rubies/ruby-1.9.1-p431/lib/ruby/1.9.1/net/http.rb:564:in
start' from /home/btm/.rvm/rubies/ruby-1.9.1-p431/lib/ruby/1.9.1/net/http.rb:1094:in request’
from
/home/btm/.rvm/gems/ruby-1.9.1-p431/gems/chef-0.10.4/lib/chef/rest/rest_request.rb:84:in
block in call' from /home/btm/.rvm/gems/ruby-1.9.1-p431/gems/chef-0.10.4/lib/chef/rest/rest_request.rb:99:in hide_net_http_bug’
from
/home/btm/.rvm/gems/ruby-1.9.1-p431/gems/chef-0.10.4/lib/chef/rest/rest_request.rb:83:in
call' from /home/btm/.rvm/gems/ruby-1.9.1-p431/gems/chef-0.10.4/lib/chef/rest.rb:219:in block in api_request’
from
/home/btm/.rvm/gems/ruby-1.9.1-p431/gems/chef-0.10.4/lib/chef/rest.rb:288:in
retriable_rest_request' from /home/btm/.rvm/gems/ruby-1.9.1-p431/gems/chef-0.10.4/lib/chef/rest.rb:218:in api_request’
from
/home/btm/.rvm/gems/ruby-1.9.1-p431/gems/chef-0.10.4/lib/chef/rest.rb:130:in
put_rest' from /home/btm/.rvm/gems/ruby-1.9.1-p431/gems/chef-0.10.4/lib/chef/node.rb:626:in save’
from (irb):9
from
/home/btm/.rvm/gems/ruby-1.9.1-p431/gems/chef-0.10.4/lib/chef/shef.rb:73:in
block in start' from /home/btm/.rvm/gems/ruby-1.9.1-p431/gems/chef-0.10.4/lib/chef/shef.rb:72:in catch’
from
/home/btm/.rvm/gems/ruby-1.9.1-p431/gems/chef-0.10.4/lib/chef/shef.rb:72:in
start' from /home/btm/.rvm/gems/ruby-1.9.1-p431/gems/chef-0.10.4/bin/shef:34:in <top (required)>’
from /home/btm/.rvm/gems/ruby-1.9.1-p431/bin/shef:19:in load' from /home/btm/.rvm/gems/ruby-1.9.1-p431/bin/shef:19:in 'chef >
quit

What does this module do ?
–add-module=../nginx-x-rid-header

It adds a header line with a uuid for associating frontend and backend
requests.

It fails without that module as well with this configuration:

nginx: nginx version: nginx/1.1.6
nginx: built by gcc 4.4.3 (Ubuntu 4.4.3-4ubuntu5)
nginx: TLS SNI support enabled
nginx: configure arguments: --conf-path=/etc/nginx
–prefix=/tmp/nginx-1.1.6 --with-http_ssl_module
–with-http_stub_status_module --with-debug

Bryan

4

Hello!

On Tue, Nov 01, 2011 at 09:13:44AM -0400, Bryan McLellan wrote:

On Tue, Nov 1, 2011 at 2:21 AM, Igor S. [email protected] wrote:

Could you create debug log:
A debugging log

nginx timeout (http 408) when sending unicode · GitHub

2011/11/01 12:44:23 [debug] 13689#0: *129 http header: “Content-Length:
16385”
…
2011/11/01 12:44:23 [debug] 13689#0: *129 http header: “User-Agent: Chef
Client/0.10.4 (ruby-1.9.1-p431; ohai-0.6.10; x86_64-linux;
+http://opscode.com)”
…

Note: content length is 16385.

…
2011/11/01 12:44:23 [debug] 13689#0: *129 http read client request body
2011/11/01 12:44:23 [debug] 13689#0: *129 SSL_read: -1
2011/11/01 12:44:23 [debug] 13689#0: *129 SSL_get_error: 2
2011/11/01 12:44:23 [debug] 13689#0: *129 http client request body recv
-2
2011/11/01 12:44:23 [debug] 13689#0: *129 http client request body rest
16385
…
2011/11/01 12:44:24 [debug] 13689#0: *129 http read client request body
2011/11/01 12:44:24 [debug] 13689#0: *129 SSL_read: 8192
2011/11/01 12:44:24 [debug] 13689#0: *129 http client request body recv
8192
…
2011/11/01 12:44:24 [debug] 13689#0: *129 SSL_read: 8192
2011/11/01 12:44:24 [debug] 13689#0: *129 http client request body recv
8192
2011/11/01 12:44:24 [debug] 13689#0: *129 write: 13, 0870D8E0, 8192,
8192
2011/11/01 12:44:24 [debug] 13689#0: *129 SSL_read: -1
2011/11/01 12:44:24 [debug] 13689#0: *129 SSL_get_error: 2
2011/11/01 12:44:24 [debug] 13689#0: *129 http client request body recv
-2
2011/11/01 12:44:24 [debug] 13689#0: *129 http client request body rest
1

Here 16384 bytes has been read from client, and one byte remains
(“rest 1”). OpenSSL doesn’t provide any more bytes and claims it
needs more network input (2, SSL_ERROR_WANT_READ).

2011/11/01 12:44:24 [debug] 13689#0: *129 event timer del: 12:
1596563798
2011/11/01 12:44:24 [debug] 13689#0: *129 event timer add: 12:
60000:1596564354
2011/11/01 12:45:24 [debug] 13689#0: *129 event timer del: 12:
1596564354
2011/11/01 12:45:24 [debug] 13689#0: *129 http run request:
“/organizations/opscode-btm/nodes/broken?”
2011/11/01 12:45:24 [debug] 13689#0: *129 http finalize request: 408,
“/organizations/opscode-btm/nodes/broken?” a:1, c:1

Though client fails to provide one more byte.

For me, it looks like problem in client. It’s either calculate
content length incorrectly or fails to properly flush ssl buffers
on it’s side.

Maxim D.