NGINX crash

aris · August 7, 2012, 4:39pm

Hello,
“nginx” crashes in “ngx_http_limit_req_handler”.
This does not happen, if “limit_req” is not nested.
We couldn’t reproduce this issue in a testing environment.
Thanks a lot

Request

GET / HTTP/1.1
Host: hostname.com
X-REAL-IP: 123.123.12.123

Config (simplified)

http {
# ipaddress + ipaddress/16 + ipaddress/24
map $http_x_real_ip $ipaddress {
default $remote_addr;
“~^\d+.\d+.\d+.\d+$” $http_x_real_ip;
}
map $ipaddress $ipaddress_net {
default “”;
“~^(?P\d+.\d+).\d+.\d+$” $ip;
}
map $ipaddress $ipaddress_host {
default “”;
“~^(?P\d+.\d+.\d+).\d+$” $ip;
}

# limit requests
limit_req_log_level         warn;
limit_req_zone              $ipaddress  zone=staticzone_ip:32m

rate=100r/s;
limit_req zone=staticzone_ip burst=50;
limit_req_zone $ipaddress zone=dynamiczone_ip:32m
rate=2r/s;
limit_req_zone $ipaddress zone=dynamiczone_ddos:32m
rate=6r/m;
limit_req_zone $ipaddress_host
zone=dynamiczone_host:32m rate=10r/s;
limit_req_zone $ipaddress_net zone=dynamiczone_net:32m
rate=20r/s;

server {
    location / {
        limit_req           zone=dynamiczone_ip burst=10;
        limit_req           zone=dynamiczone_ddos burst=1000

nodelay;
limit_req zone=dynamiczone_host burst=20;
limit_req zone=dynamiczone_net burst=40;

        fastcgi_pass        unix:/var/run/fastcgi.sock;
        ...
    }
}

}

Backtrace

#0 0x000000000040b25d in ngx_vslprintf (buf=0x7fff4f9be1df “”,
last=0x7fff4f9be970 “0”, fmt=0x48231b “v"”, args=0x7fff4f9be970) at
src/core/ngx_string.c:245
p = 0x7fff4f9be192 “0: *1901681 the value of the "ipaddress"
variable is more than 65535 bytes: "”
zero = 32 ’ ’
d = 0
f = 6.9058890903168798e-310
len = 1937
slen = 18446744073709551615
i64 = 0
ui64 = 0
frac = 0
ms = 140734529003968
width = 0
sign = 1
hex = 0
max_width = 0
frac_width = 0
scale = 18446744070750200624
n = 0
v = 0x1b958148
vv = 0x1b99a040

#1 0x000000000040535c in ngx_log_error_core (level=4, log=0x1b9f0e70,
err=0, fmt=0x4822e0 “the value of the "%V" variable is more than 65535
bytes: "%v"”) at src/core/ngx_log.c:120
args = {{gp_offset = 48, fp_offset = 48, overflow_arg_area =
0x7fff4f9bea70, reg_save_area = 0x7fff4f9be9a0}}
p = 0x7fff4f9be19e “the value of the "ipaddress" variable is
more than 65535 bytes: "”
last = 0x7fff4f9be970 “0”
msg = 0x7fff4f9be19e “the value of the "ipaddress" variable is
more than 65535 bytes: "”
errstr = “2012/08/07 16:17:42 [error] 30667#0: 1901681 the
value of the "ipaddress" variable is more than 65535 bytes:
"\000\000\000\000\000\000\000\000\000>\001\000\006\000\000\000\000`\233\231\033\000\000\000\000\303)\000\000\000\000\000\000\341\346\233O\377\177\000\000he\233\033\000\000\000\000V\\000\000\000\000\000\000\000\200\001\000\000\000\000\000pd\233\033\000\000\000\000p\312s\033\371\000\000\000\000\000\000\000\000\000\000P\363\233O\377\177\000\000\020c\233\033\000\000\000\000”…

#2 0x000000000046d5d2 in ngx_http_limit_req_handler (r=0x1b99faa0) at
src/http/modules/ngx_http_limit_req_module.c:192
len = 194343136
hash = 4294967295
rc = -5
n = 0
excess = 0
delay = 463076000
vv = 0x1b99a040
ctx = 0x1b958128
lrcf = 0x1b9594a0
limit = 0x1b959f00
limits = 0x1b959f00

#3 0x0000000000437b08 in ngx_http_core_generic_phase (r=0x1b99faa0,
ph=0x1b968e58) at src/http/ngx_http_core_module.c:899
rc = -5

#4 0x0000000000437ab6 in ngx_http_core_run_phases (r=0x1b99faa0) at
src/http/ngx_http_core_module.c:877
rc = -2
ph = 0x1b968df8
cmcf = 0x1b932278

#5 0x0000000000437a32 in ngx_http_handler (r=0x1b99faa0) at
src/http/ngx_http_core_module.c:860
cmcf = 0x2af91c2ba0a8

#6 0x000000000044459c in ngx_http_process_request (r=0x1b99faa0) at
src/http/ngx_http_request.c:1688
c = 0x2af91b73d258

#7 0x0000000000443259 in ngx_http_process_request_headers
(rev=0x2af91c2ba0a8) at src/http/ngx_http_request.c:1132
p = 0x10 <Address 0x10 out of bounds>
len = 463051616
n = 43
rc = 0
rv = 140734529006688
h = 0x1b99a1c0
c = 0x2af91b73d258
hh = 0x0
r = 0x1b99faa0
cscf = 0x1b963668
cmcf = 0x1b932278

#8 0x0000000000442afe in ngx_http_process_request_line
(rev=0x2af91c2ba0a8) at src/http/ngx_http_request.c:932
host = 0x1b999b60 “\211\245\231\033”
n = 58
rc = 0
rv = 368
c = 0x2af91b73d258
r = 0x1b99faa0
cscf = 0x1b99a020

#9 0x00000000004423b5 in ngx_http_init_request (rev=0x2af91c2ba0a8) at
src/http/ngx_http_request.c:519
tp = 0x6975a0
i = 463074232
c = 0x2af91b73d258
r = 0x1b99faa0
sin = 0x7fff4f9bed70
port = 0x1b969230
addr = 0x1b969240
ctx = 0x1b9f0eb0
addr_conf = 0x1b969248
hc = 0x1b9f0ec8
cscf = 0x1b963668
clcf = 0x1b963700
cmcf = 0x1b932278

#10 0x00000000004328b2 in ngx_epoll_process_events (cycle=0x1b9316c0,
timer=500, flags=1) at src/event/modules/ngx_epoll_module.c:679
events = 1
revents = 1
instance = 1
i = 0
level = 1335619040
err = 0
rev = 0x2af91c2ba0a8
wev = 0x428d62
queue = 0x0
c = 0x2af91b73d258

#11 0x0000000000425dc0 in ngx_process_events_and_timers
(cycle=0x1b9316c0) at src/event/ngx_event.c:247
flags = 1
timer = 500
delta = 1344349062687

#12 0x0000000000430d04 in ngx_worker_process_cycle (cycle=0x1b9316c0,
data=0x0) at src/os/unix/ngx_process_cycle.c:808
i = 140734529008464
c = 0x0

#13 0x000000000042dda1 in ngx_spawn_process (cycle=0x1b9316c0,
proc=0x430bb0 <ngx_worker_process_cycle>, data=0x0, name=0x47d6c8
“worker process”, respawn=-4) at src/os/unix/ngx_process.c:198
on = 1
pid = 0
s = 6

#14 0x000000000042ffd7 in ngx_start_worker_processes (cycle=0x1b9316c0,
n=4, type=-4) at src/os/unix/ngx_process_cycle.c:365
i = 2
ch = {command = 1, pid = 30666, slot = 5, fd = 15}

#15 0x000000000042fbf7 in ngx_master_process_cycle (cycle=0x1b9316c0) at
src/os/unix/ngx_process_cycle.c:250
title = 0x1b94e44b “”
p = 0x1b94e48d “”
size = 67
i = 3
n = 462608624
sigio = 0
set = {__val = {0 <repeats 16 times>}}
itv = {it_interval = {tv_sec = 0, tv_usec = 0}, it_value =
{tv_sec = 8, tv_usec = 18}}
live = 1
delay = 0
ls = 0x4
ccf = 0x1b931ce8

#16 0x0000000000403280 in main (argc=3, argv=0x7fff4f9bf358) at
src/core/nginx.c:410
i = 30
log = 0x697300
cycle = 0x1b92d6b0
init_cycle = {conf_ctx = 0x0, pool = 0x1b92c930, log = 0x697300,
new_log = {log_level = 0, file = 0x0, connection = 0, handler = 0, data
= 0x0, action = 0x0}, files = 0x0,
free_connections = 0x0, free_connection_n = 0,
reusable_connections_queue = {prev = 0x0, next = 0x0}, listening = {elts
= 0x1b92ce80, nelts = 1, size = 200, nalloc = 10,
pool = 0x1b92c930}, pathes = {elts = 0x0, nelts = 0, size =
0, nalloc = 0, pool = 0x0}, open_files = {last = 0x0, part = {elts =
0x0, nelts = 0, next = 0x0}, size = 0,
nalloc = 0, pool = 0x0}, shared_memory = {last = 0x0, part =
{elts = 0x0, nelts = 0, next = 0x0}, size = 0, nalloc = 0, pool = 0x0},
connection_n = 0, files_n = 0,
connections = 0x0, read_events = 0x0, write_events = 0x0,
old_cycle = 0x0, conf_file = {len = 20, data = 0x7fff4f9c0e91 “”},
conf_param = {len = 0, data = 0x0}, conf_prefix = {
len = 10, data = 0x7fff4f9c0e91 “”}, prefix = {len = 17,
data = 0x47a67e “/usr/local/nginx/”}, lock_file = {len = 0, data = 0x0},
hostname = {len = 0, data = 0x0}}
ccf = 0x1b92ded8

Posted at Nginx Forum:

casper_the_ghost · August 7, 2012, 10:51pm

It does not crash if I remove the limit_req “dynamiczone_net”.

Posted at Nginx Forum:

casper_the_ghost · August 8, 2012, 12:15pm

Hello!

On Tue, Aug 07, 2012 at 10:38:59AM -0400, double wrote:

Hello,
“nginx” crashes in “ngx_http_limit_req_handler”.
This does not happen, if “limit_req” is not nested.
We couldn’t reproduce this issue in a testing environment.
Thanks a lot

What does nginx -V show on the affected host? Any 3rd party
modules/patches? Which OS, which PCRE library version? Are
hardware problems ruled out (i.e. are you able to reproduce the
problem on another host)?

It would be cool if you could obtain debug log.

Request

GET / HTTP/1.1
Host: hostname.com
X-REAL-IP: 123.123.12.123

Is it actual request which corresponds to a backtrace below?

Config (simplified)

http {
# ipaddress + ipaddress/16 + ipaddress/24
map $http_x_real_ip $ipaddress {
default $remote_addr;
“~^\d+.\d+.\d+.\d+$” $http_x_real_ip;
}

It would be better to see full actual config used.

[…]

    errstr = "2012/08/07 16:17:42 [error] 30667#0: *1901681 the
    delay = 463076000
    vv = 0x1b99a040
    ctx = 0x1b958128
    lrcf = 0x1b9594a0
    limit = 0x1b959f00
    limits = 0x1b959f00

It looks like the $ipaddress variable was corrupted somehow. Could
you please show

fr 2
p *limit
p *ctx
p *vv
p *r

output from gdb?

[…]

Maxim D.

casper_the_ghost · August 8, 2012, 12:01pm

On Tuesday 07 August 2012 18:38:59 double wrote:

Hello,
“nginx” crashes in “ngx_http_limit_req_handler”.
This does not happen, if “limit_req” is not nested.
We couldn’t reproduce this issue in a testing environment.
Thanks a lot

[…]

Could you provide debug log with crash or/and core dump?

http://nginx.org/en/docs/debugging_log.html

wbr, Valentin V. Bartenev

casper_the_ghost · August 10, 2012, 9:51pm

Hello,

Thanks a lot for your answer.
The machine runs CentOS5 (PCRE from repository).
I must say, we never had a single crash - not even once.
If we telnet the above request, NGINX crashes immediately.
For full config or core-dumps please contact us per email:
sandyherman [at] gmx [dot] net

Thanks a lot
Sandy

“http_fastcgi_module”, “http_limit_conn_module”,

“http_limit_req_module”
./configure --prefix=/usr/local/nginx --user=www --group=www
–with-pcre
–without-http_charset_module --without-http_gzip_module
–without-http_ssi_module --without-http_userid_module
–without-http_autoindex_module --without-http_geo_module
–without-http_split_clients_module
–without-http_referer_module --without-http_proxy_module
–without-http_uwsgi_module --without-http_scgi_module
–without-http_memcached_module --without-http_empty_gif_module
–without-http_browser_module
–without-http_upstream_ip_hash_module
–without-mail_pop3_module --without-mail_imap_module
–without-mail_smtp_module

(gdb) fr 2
#2 0x000000000046d5d2 in ngx_http_limit_req_handler (r=0x1b99faa0) at
src/http/modules/ngx_http_limit_req_module.c:192
192 in src/http/modules/ngx_http_limit_req_module.c

(gdb) p *limit
$1 = {shm_zone = 0x1b9319e8, burst = 10000, nodelay = 0}

(gdb) p *ctx
$2 = {sh = 0x2af913765000, shpool = 0x2af913735000, rate = 2000, index =
2, var = {len = 9, data = 0x1b9580f9 “ipaddress”}, node = 0x0}

(gdb) p *vv
$3 = {len = 194343136, valid = 1, no_cacheable = 0, not_found = 0,
escape = 0, data = 0x0}

(gdb) p r
$4 = {signature = 1347703880, connection = 0x2af91b73d258, ctx =
0x1b999f70, main_conf = 0x1b932068, srv_conf = 0x1b958310, loc_conf =
0x1b9590e8,
read_event_handler = 0x445737 <ngx_http_block_reading>,
write_event_handler = 0x437a34 <ngx_http_core_run_phases>, cache = 0x0,
upstream = 0x0, upstream_states = 0x0, pool = 0x1b999b60,
header_in = 0x1ba0dba0, headers_in = {headers = {last = 0x1b99fb10,
part = {elts = 0x1b99a190, nelts = 2, next = 0x0}, size = 48, nalloc =
20, pool = 0x1b999b60}, host = 0x1b99a190,
connection = 0x0, if_modified_since = 0x0, if_unmodified_since =
0x0, user_agent = 0x0, referer = 0x0, content_length = 0x0, content_type
= 0x0, range = 0x0, if_range = 0x0,
transfer_encoding = 0x0, expect = 0x0, authorization = 0x0,
keep_alive = 0x0, user = {len = 0, data = 0x0}, passwd = {len = 0, data
= 0x0}, cookies = {elts = 0x1b99a550, nelts = 0,
size = 8, nalloc = 2, pool = 0x1b999b60}, server = {len = 9, data
= 0x1b9c7625 “seite.net”}, content_length_n = -1, keep_alive_n = -1,
connection_type = 0, msie = 0, msie6 = 0,
opera = 0, gecko = 0, chrome = 0, safari = 0, konqueror = 0},
headers_out = {headers = {last = 0x1b99fc28, part = {elts = 0x1b999bb0,
nelts = 0, next = 0x0}, size = 48, nalloc = 20,
pool = 0x1b999b60}, status = 0, status_line = {len = 0, data =
0x0}, server = 0x0, date = 0x0, content_length = 0x0, content_encoding =
0x0, location = 0x0, refresh = 0x0,
last_modified = 0x0, content_range = 0x0, accept_ranges = 0x0,
www_authenticate = 0x0, expires = 0x0, etag = 0x0, override_charset =
0x0, content_type_len = 0, content_type = {len = 0,
data = 0x0}, charset = {len = 0, data = 0x0}, content_type_lowcase
= 0x0, content_type_hash = 0, cache_control = {elts = 0x0, nelts = 0,
size = 0, nalloc = 0, pool = 0x0},
content_length_n = -1, date_time = 0, last_modified_time = -1},
request_body = 0x0, lingering_time = 0, start_sec = 1344349062,
start_msec = 773, method = 2, http_version = 1001,
request_line = {len = 14, data = 0x1b9c7610 “GET / HTTP/1.1\nHost”},
uri = {len = 1, data = 0x1b9c7614 “/ HTTP/1.1\nHost”}, args = {len = 0,
data = 0x0}, exten = {len = 0, data = 0x0},
unparsed_uri = {len = 1, data = 0x1b9c7614 “/ HTTP/1.1\nHost”},
method_name = {len = 3, data = 0x1b9c7610 “GET / HTTP/1.1\nHost”},
http_protocol = {len = 8,
data = 0x1b9c7616 “HTTP/1.1\nHost”}, out = 0x0, main = 0x1b99faa0,
parent = 0x0, postponed = 0x0, post_subrequest = 0x0, posted_requests =
0x0, virtual_names = 0x1b969258,
phase_handler = 4, content_handler = 0x472884
<ngx_http_fastcgi_handler>, access_code = 0, variables = 0x1b99a020,
ncaptures = 0, captures = 0x0,
captures_data = 0x1b99a56d
"195.162.24.220195.162.24.220\356(F\256ܱz:\365\311&\337bog\267I\265ۉ\324:E\027\225Y\265)!MiL\262\177/\207\303\021\243]\260t\335శ\222\302\316)dmL\312*i\333ۏM3\317ah\350\313\\024\204g\a\211\030\306H\370\f\360\f\321\351L\216\f",
limit_rate = 65536, header_size = 0, request_length = 58, err_status =
0, http_connection = 0x1b9f0ec8,
log_handler = 0x446b6e <ngx_http_log_error_handler>, cleanup = 0x0,
subrequests = 201, count = 1, blocked = 0, aio = 0, http_state = 2,
complex_uri = 0, quoted_uri = 0, plus_in_uri = 0,
space_in_uri = 0, invalid_header = 0, add_uri_to_alias = 0,
valid_location = 1, valid_unparsed_uri = 1, uri_changed = 0, uri_changes
= 11, request_body_in_single_buf = 0,
request_body_in_file_only = 0, request_body_in_persistent_file = 0,
request_body_in_clean_file = 0, request_body_file_group_access = 0,
request_body_file_log_level = 5,
subrequest_in_memory = 0, waited = 0, cached = 0, proxy = 0,
bypass_cache = 0, no_cache = 0, limit_conn_set = 0, limit_req_set = 0,
pipeline = 0, plain_http = 0, chunked = 0,
header_only = 0, keepalive = 1, lingering_close = 0, discard_body = 0,
internal = 0, error_page = 0, ignore_content_encoding = 0,
filter_finalize = 0, post_action = 0,
request_complete = 0, request_output = 0, header_sent = 0,
expect_tested = 0, root_tested = 0, done = 0, logged = 0, buffered = 0,
main_filter_need_in_memory = 0,
filter_need_in_memory = 0, filter_need_temporary = 0, allow_ranges =
0, state = 0, header_hash = 103689151937377, lowcase_index = 9,
lowcase_header = “x-real-ip”, ‘\000’ <repeats 22 times>,
header_name_start = 0x1b9c7649 “\net”, header_name_end = 0x1b9c7638 “”,
header_start = 0x1b9c763a “195.162.24.220”,
header_end = 0x1b9c7649 “\net”, uri_start = 0x1b9c7614 “/
HTTP/1.1\nHost”, uri_end = 0x1b9c7615 " HTTP/1.1\nHost", uri_ext = 0x0,
args_start = 0x0,
request_start = 0x1b9c7610 “GET / HTTP/1.1\nHost”, request_end =
0x1b9c761e “\nHost”, method_end = 0x1b9c7612 “T / HTTP/1.1\nHost”,
schema_start = 0x0, schema_end = 0x0, host_start = 0x0,
host_end = 0x0, port_start = 0x0, port_end = 0x0, http_minor = 1,
http_major = 1}

Posted at Nginx Forum:

casper_the_ghost · August 13, 2012, 4:27am

Hello!

On Fri, Aug 10, 2012 at 03:51:15PM -0400, double wrote:

[…]

2, var = {len = 9, data = 0x1b9580f9 “ipaddress”}, node = 0x0}

(gdb) p *vv
$3 = {len = 194343136, valid = 1, no_cacheable = 0, not_found = 0,
escape = 0, data = 0x0}

[…]

Ok, it looks like I see the problem. It might be triggered if the
same variable is used multiple times on a right side of a map.
Attached patch should fix this.

Maxim D.

casper_the_ghost · August 16, 2012, 2:29pm

Hello!

On Mon, Aug 13, 2012 at 07:46:56PM -0400, double wrote:

Hi Maxim,

Patch works.
You are definitly a genius.

Thanks a lot

Patch committed, thanks for testing.

Maxim D.

casper_the_ghost · August 14, 2012, 1:47am

Hi Maxim,

Patch works.
You are definitly a genius.

Thanks a lot

Posted at Nginx Forum: