http2 client abort when upstream cause segment fault

[crasyangel.lhy@…]

client canceled stream while reading response header from upstream

log:
"2018/05/13 23:11:07 [info] 124561#0: *198618980 client canceled stream 13 while reading response header from upstream"

then execute:
ev = fc->read;
ev->handler(ev);

ev->handler would be ngx_http_v2_close_stream_handler, then ngx_http_free_request

request still used in ngx_http_upstream_handler, because upstream did not close when close stream

segment fault stacktrace:
(gdb) bt
Python Exception <type 'exceptions.ImportError'> No module named gdb.frames:
#0 ngx_http_upstream_handler (ev=0x7f5e16447c60) at src/http/ngx_http_upstream.c:1261
#1 0x000000000047bb16 in ngx_event_expire_timers () at src/event/ngx_event_timer.c:96
#2 0x000000000047b5af in ngx_process_events_and_timers (cycle=cycle@entry=0x1320bf0) at src/event/ngx_event.c:263
#3 0x00000000004834dc in ngx_worker_process_cycle (cycle=0x1320bf0, data=<optimized out>) at src/os/unix/ngx_process_cycle.c:749
#4 0x0000000000481ba2 in ngx_spawn_process (cycle=cycle@entry=0x1320bf0, proc=proc@entry=0x483449 <ngx_worker_process_cycle>, data=data@entry=0x4,

name=name@entry=0x76c9d6 "worker process", respawn=respawn@entry=-3) at src/os/unix/ngx_process.c:198

#5 0x000000000048278e in ngx_start_worker_processes (cycle=cycle@entry=0x1320bf0, n=6, type=type@entry=-3) at src/os/unix/ngx_process_cycle.c:358
#6 0x0000000000483e45 in ngx_master_process_cycle (cycle=cycle@entry=0x1320bf0) at src/os/unix/ngx_process_cycle.c:130
#7 0x000000000045bd6e in main (argc=<optimized out>, argv=<optimized out>) at src/core/nginx.c:382

[crasyangel.lhy@…]

client canceled stream while reading response header from upstream
log:
"2018/05/13 23:11:07 [info] 124561#0: *198618980 client canceled stream 13 while reading response header from upstream"
then execute:
ev = fc->read;
ev->handler(ev);
ev->handler would be ngx_http_v2_close_stream_handler, then ngx_http_free_request
request still used in ngx_http_upstream_handler, because upstream did not close when close stream
segment fault stacktrace:
(gdb) bt
Python Exception <type 'exceptions.ImportError?'> No module named gdb.frames:
#0 ngx_http_upstream_handler (ev=0x7f5e16447c60) at src/http/ngx_http_upstream.c:1261
#1 0x000000000047bb16 in ngx_event_expire_timers () at src/event/ngx_event_timer.c:96
#2 0x000000000047b5af in ngx_process_events_and_timers (cycle=cycle@entry=0x1320bf0) at src/event/ngx_event.c:263
#3 0x00000000004834dc in ngx_worker_process_cycle (cycle=0x1320bf0, data=<optimized out>) at src/os/unix/ngx_process_cycle.c:749
#4 0x0000000000481ba2 in ngx_spawn_process (cycle=cycle@entry=0x1320bf0, proc=proc@entry=0x483449 <ngx_worker_process_cycle>, data=data@entry=0x4,
name=name@entry=0x76c9d6 "worker process", respawn=respawn@entry=-3) at src/os/unix/ngx_process.c:198
#5 0x000000000048278e in ngx_start_worker_processes (cycle=cycle@entry=0x1320bf0, n=6, type=type@entry=-3) at src/os/unix/ngx_process_cycle.c:358
#6 0x0000000000483e45 in ngx_master_process_cycle (cycle=cycle@entry=0x1320bf0) at src/os/unix/ngx_process_cycle.c:130
#7 0x000000000045bd6e in main (argc=<optimized out>, argv=<optimized out>) at src/core/nginx.c:382

GaoYan.

[Maxim Dounin]

Could you please show full "nginx -V" output?

[crasyangel.lhy@…]

Replying to mdounin:

Could you please show full "nginx -V" output?

nginx version: nginx/1.12.2
built by gcc 4.8.3 (GCC)
built with OpenSSL 1.0.2h 3 May 2016
TLS SNI support enabled
configure arguments: --with-debug --with-ipv6 --with-http_v2_module --with-http_spdy_module --add-module=addon/jstart --add-module=addon/upstream_jhash --add-module=addon/upstream_jconhash --add-module=addon/upstream_jprobe --add-module=addon/upstream_jdomain --add-module=addon/upstream_jhealth_check --add-module=addon/jflow_control --add-module=addon/jflv --add-module=addon/ps_imgpack --add-module=addon/jpartition --add-module=addon/jdisposition --add-module=addon/jstore --add-module=addon/jchecksum --add-module=addon/jbilling --add-module=addon/headers-more-nginx-module-0.33 --add-module=addon/blowfish --add-module=addon/jcheck --add-module=addon/bmat --add-module=addon/bmat2 --add-module=addon/bmat_lua --add-module=addon/bmat2_lua --add-module=addon/md5check --add-module=addon/jcrc --add-module=addon/jurl_decrypt_blowfish --add-module=addon/jfirst_byte --add-module=addon/hntv_log --add-module=addon/hntv_pno_billing --add-module=addon/qq_sdtfrom_billing --add-module=addon/server_internal_rechange --add-module=addon/server_302_rechange --add-module=addon/ngx_http_jtoken_module --add-module=addon/jvip --add-module=addon/urlban --with-http_stub_status_module --with-pcre=addon/pcre-8.01/ --with-ld-opt='-lstdc++ -std=c99' --with-cc-opt=-DNGX_SSLKEY_LIB --with-openssl=third-lib/openssl-1.0.2h --with-openssl-opt=-lpthread --with-http_gunzip_module --with-http_realip_module --with-http_ssl_module --add-module=addon/lua-nginx-module-0.10.11 --add-module=addon/lua-get-conf --add-module=addon/pcs_rate_limit --add-module=addon/global_rate_limit --add-module=addon/ngx_devel_kit-0.2.19 --add-module=addon/lua-dynamic-upstream --add-module=addon/log-split --add-module=addon/decrypt_uri --add-module=addon/silent_limit_req --add-module=addon/ngx_http_iplib_module --add-module=addon/lua-upstream-nginx-module --add-module=addon/sslkey --prefix=output

[Maxim Dounin]

Are you able to reproduce the problem without 3rd party modules compiled in?

[crasyangel.lhy@…]

Very difficult, only few core with thousands machines during several months
We observed this core only occur with http2 request, and it's almost nothing to do with 3rd party modules

Check this:
loggingHost:wz4ct-jorcol-64 2018/05/14 13:37:21 [error] 147050#0: *221733769 peer closed connection in SSL handshake while sending request to upstream, client: 47.98.142.42, server: , request: "OPTIONS /v1/webconf HTTP/2.0"
loggingHost:wz4ct-jorcol-64 2018/05/14 13:37:21 [alert] 147050#0: *221733769 http request count is zero while sending to client, client: 47.98.142.42, server: , request: "OPTIONS /v1/webconf HTTP/2.0"

Some info is sensitive, and we add some info in nginx source, but no any serious changes

Can you explain how upstream close when http2 client or stream closed prematurely?

Replying to mdounin:

Are you able to reproduce the problem without 3rd party modules compiled in?

[crasyangel.lhy@…]

Strange, upstream closed really

if (c->error) {

if ((ngx_event_flags & NGX_USE_LEVEL_EVENT) && ev->active) {

event = ev->write ? NGX_WRITE_EVENT : NGX_READ_EVENT;

if (ngx_del_event(ev, event, 0) != NGX_OK) {

ngx_http_upstream_finalize_request(r, u,

NGX_HTTP_INTERNAL_SERVER_ERROR);

return;

}

}

if (!u->cacheable) {

ngx_http_upstream_finalize_request(r, u,

NGX_HTTP_CLIENT_CLOSED_REQUEST);

}

return;

}

#if (NGX_HTTP_V2)

if (r->stream) {

return;

}

#endif

[Maxim Dounin]

Can you explain how upstream close when http2 client or stream closed prematurely?

Event if ngx_http_v2_close_stream_handler() is indeed called while an upstream connection is running (this shouldn't happen, as ngx_http_process_request() will set its own handlers), the ngx_http_free_request() will run cleanup handlers which will correctly close the upstream connection. As such, the scenario you describe is clearly not possible with vanilla nginx code.

On the other hand, the segmentation fault and errors shown can be easily triggered by a bug in a 3rd party module, or your local code modifications.

I'm closing this, as clearly this is not something can be diagnosed as an nginx problem, and more likely a problem in the external code. If you'll be able to reproduce this using unmodified nginx without 3rd party modules, please reopen this ticket with additional details.