---------- Forwarded message ---------- From: <nginx-devel-requ...@nginx.org> Date: 2014-05-16 5:00 GMT-07:00 Subject: nginx-devel Digest, Vol 55, Issue 15 To: nginx-devel@nginx.org
Send nginx-devel mailing list submissions to nginx-devel@nginx.org To subscribe or unsubscribe via the World Wide Web, visit http://mailman.nginx.org/mailman/listinfo/nginx-devel or, via email, send a message with subject or body 'help' to nginx-devel-requ...@nginx.org You can reach the person managing the list at nginx-devel-ow...@nginx.org When replying, please edit your Subject line so it is more specific than "Re: Contents of nginx-devel digest..." Today's Topics: 1. [nginx] SPDY: set log action for PROXY protocol only while parsi... (Valentin Bartenev) 2. [nginx] SPDY: improved logging. (Valentin Bartenev) 3. [nginx] SPDY: refactored ngx_http_spdy_state_headers(). (Valentin Bartenev) 4. [nginx] SPDY: added a debug point to the state buffer overflow p... (Valentin Bartenev) 5. [nginx] SPDY: added protection from overrun of the receive buffer. (Valentin Bartenev) ---------------------------------------------------------------------- Message: 1 Date: Thu, 15 May 2014 15:25:50 +0000 From: Valentin Bartenev <vb...@nginx.com> To: nginx-devel@nginx.org Subject: [nginx] SPDY: set log action for PROXY protocol only while parsi... Message-ID: <hg.ed5fb7d22d46.1400167550.6369085454036692...@ns.nginx.org> Content-Type: text/plain; charset="us-ascii" details: http://hg.nginx.org/nginx/rev/ed5fb7d22d46 branches: changeset: 5692:ed5fb7d22d46 user: Valentin Bartenev <vb...@nginx.com> date: Thu May 15 19:22:06 2014 +0400 description: SPDY: set log action for PROXY protocol only while parsing it. Handling of PROXY protocol for SPDY connection is currently implemented as a SPDY state. And while nginx waiting for PROXY protocol data it continues to process SPDY connection: initializes zlib context, sends control frames. diffstat: src/http/ngx_http_spdy.c | 17 +++++++++-------- 1 files changed, 9 insertions(+), 8 deletions(-) diffs (40 lines): diff -r 31349361558e -r ed5fb7d22d46 src/http/ngx_http_spdy.c --- a/src/http/ngx_http_spdy.c Wed Apr 30 20:34:20 2014 +0400 +++ b/src/http/ngx_http_spdy.c Thu May 15 19:22:06 2014 +0400 @@ -424,12 +424,8 @@ ngx_http_spdy_init(ngx_event_t *rev) sc->init_window = NGX_SPDY_INIT_STREAM_WINDOW; - sc->handler = ngx_http_spdy_state_head; - - if (hc->proxy_protocol) { - c->log->action = "reading PROXY protocol"; - sc->handler = ngx_http_spdy_proxy_protocol; - } + sc->handler = hc->proxy_protocol ? ngx_http_spdy_proxy_protocol + : ngx_http_spdy_state_head; sc->zstream_in.zalloc = ngx_http_spdy_zalloc; sc->zstream_in.zfree = ngx_http_spdy_zfree; @@ -823,14 +819,19 @@ static u_char * ngx_http_spdy_proxy_protocol(ngx_http_spdy_connection_t *sc, u_char *pos, u_char *end) { + ngx_log_t *log; + + log = sc->connection->log; + log->action = "reading PROXY protocol"; + pos = ngx_proxy_protocol_parse(sc->connection, pos, end); + log->action = "processing SPDY"; + if (pos == NULL) { return ngx_http_spdy_state_protocol_error(sc); } - sc->connection->log->action = "processing SPDY"; - return ngx_http_spdy_state_complete(sc, pos, end); } ------------------------------ Message: 2 Date: Thu, 15 May 2014 15:25:52 +0000 From: Valentin Bartenev <vb...@nginx.com> To: nginx-devel@nginx.org Subject: [nginx] SPDY: improved logging. Message-ID: <hg.701d6e17e42c.1400167552.6369085454036692...@ns.nginx.org> Content-Type: text/plain; charset="us-ascii" details: http://hg.nginx.org/nginx/rev/701d6e17e42c branches: changeset: 5693:701d6e17e42c user: Valentin Bartenev <vb...@nginx.com> date: Wed Apr 30 20:34:20 2014 +0400 description: SPDY: improved logging. diffstat: src/http/ngx_http_spdy.c | 210 +++++++++++++++++++++++--------- src/http/ngx_http_spdy_filter_module.c | 3 +- 2 files changed, 151 insertions(+), 62 deletions(-) diffs (truncated from 656 to 300 lines): diff -r ed5fb7d22d46 -r 701d6e17e42c src/http/ngx_http_spdy.c --- a/src/http/ngx_http_spdy.c Thu May 15 19:22:06 2014 +0400 +++ b/src/http/ngx_http_spdy.c Wed Apr 30 20:34:20 2014 +0400 @@ -395,8 +395,7 @@ ngx_http_spdy_init(ngx_event_t *rev) c = rev->data; hc = c->data; - ngx_log_debug0(NGX_LOG_DEBUG_HTTP, c->log, 0, - "init spdy request"); + ngx_log_debug0(NGX_LOG_DEBUG_HTTP, c->log, 0, "init spdy request"); c->log->action = "processing SPDY"; @@ -556,7 +555,7 @@ ngx_http_spdy_read_handler(ngx_event_t * if (n == 0 && (sc->incomplete || sc->processing)) { ngx_log_error(NGX_LOG_INFO, c->log, 0, - "client closed prematurely connection"); + "client prematurely closed connection"); } if (n == 0 || n == NGX_ERROR) { @@ -644,7 +643,7 @@ ngx_http_spdy_write_handler(ngx_event_t stream->handled = 0; ngx_log_debug1(NGX_LOG_DEBUG_HTTP, c->log, 0, - "spdy run stream %ui", stream->id); + "run spdy stream %ui", stream->id); wev = stream->request->connection->write; wev->handler(wev); @@ -860,7 +859,7 @@ ngx_http_spdy_state_head(ngx_http_spdy_c pos += sizeof(uint32_t); ngx_log_debug3(NGX_LOG_DEBUG_HTTP, sc->connection->log, 0, - "spdy process frame head:%08XD f:%Xd l:%uz", + "process spdy frame head:%08XD f:%Xd l:%uz", head, sc->flags, sc->length); if (ngx_spdy_ctl_frame_check(head)) { @@ -872,6 +871,8 @@ ngx_http_spdy_state_head(ngx_http_spdy_c return ngx_http_spdy_state_syn_stream(sc, pos, end); case NGX_SPDY_SYN_REPLY: + ngx_log_error(NGX_LOG_INFO, sc->connection->log, 0, + "client sent unexpected SYN_REPLY frame"); return ngx_http_spdy_state_protocol_error(sc); case NGX_SPDY_RST_STREAM: @@ -887,6 +888,8 @@ ngx_http_spdy_state_head(ngx_http_spdy_c return ngx_http_spdy_state_skip(sc, pos, end); /* TODO */ case NGX_SPDY_HEADERS: + ngx_log_error(NGX_LOG_INFO, sc->connection->log, 0, + "client sent unexpected HEADERS frame"); return ngx_http_spdy_state_protocol_error(sc); case NGX_SPDY_WINDOW_UPDATE: @@ -904,10 +907,8 @@ ngx_http_spdy_state_head(ngx_http_spdy_c return ngx_http_spdy_state_data(sc, pos, end); } - - /* TODO version & type check */ - ngx_log_debug0(NGX_LOG_DEBUG_HTTP, sc->connection->log, 0, - "spdy unknown frame"); + ngx_log_error(NGX_LOG_INFO, sc->connection->log, 0, + "client sent invalid frame"); return ngx_http_spdy_state_protocol_error(sc); } @@ -927,7 +928,10 @@ ngx_http_spdy_state_syn_stream(ngx_http_ } if (sc->length <= NGX_SPDY_SYN_STREAM_SIZE) { - /* TODO logging */ + ngx_log_error(NGX_LOG_INFO, sc->connection->log, 0, + "client sent SYN_STREAM frame with incorrect length %uz", + sc->length); + return ngx_http_spdy_state_protocol_error(sc); } @@ -968,7 +972,7 @@ ngx_http_spdy_state_syn_stream(ngx_http_ if (sc->processing >= sscf->concurrent_streams) { ngx_log_error(NGX_LOG_INFO, sc->connection->log, 0, - "spdy concurrent streams exceeded %ui", sc->processing); + "concurrent streams exceeded %ui", sc->processing); if (ngx_http_spdy_send_rst_stream(sc, sid, NGX_SPDY_REFUSED_STREAM, prio) @@ -1026,7 +1030,7 @@ ngx_http_spdy_state_headers(ngx_http_spd r = sc->stream->request; ngx_log_debug2(NGX_LOG_DEBUG_HTTP, r->connection->log, 0, - "spdy process HEADERS %uz of %uz", size, sc->length); + "process spdy header block %uz of %uz", size, sc->length); buf = r->header_in; @@ -1101,7 +1105,7 @@ ngx_http_spdy_state_headers(ngx_http_spd buf->pos += NGX_SPDY_NV_NUM_SIZE; ngx_log_debug1(NGX_LOG_DEBUG_HTTP, r->connection->log, 0, - "spdy HEADERS block consists of %ui entries", + "spdy header block has %ui entries", sc->entries); if (ngx_list_init(&r->headers_in.headers, r->pool, 20, @@ -1142,7 +1146,6 @@ ngx_http_spdy_state_headers(ngx_http_spd rc = ngx_http_spdy_alloc_large_header_buffer(r); if (rc == NGX_DECLINED) { - /* TODO logging */ ngx_http_finalize_request(r, NGX_HTTP_REQUEST_HEADER_TOO_LARGE); return ngx_http_spdy_state_headers_skip(sc, pos, end); @@ -1179,9 +1182,8 @@ ngx_http_spdy_state_headers(ngx_http_spd } if (complete) { - /* TODO: improve error message */ ngx_log_debug0(NGX_LOG_DEBUG_HTTP, r->connection->log, 0, - "spdy again while last chunk"); + "premature end of spdy header block"); return ngx_http_spdy_state_headers_error(sc, pos, end); } @@ -1190,13 +1192,7 @@ ngx_http_spdy_state_headers(ngx_http_spd ngx_http_spdy_state_headers); case NGX_HTTP_PARSE_INVALID_HEADER: - - /* TODO: improve error message */ - ngx_log_error(NGX_LOG_INFO, r->connection->log, 0, - "client sent invalid header line"); - ngx_http_finalize_request(r, NGX_HTTP_BAD_REQUEST); - return ngx_http_spdy_state_headers_skip(sc, pos, end); default: /* NGX_ERROR */ @@ -1262,6 +1258,9 @@ ngx_http_spdy_state_headers_skip(ngx_htt ngx_http_spdy_state_headers_skip); } + ngx_log_debug2(NGX_LOG_DEBUG_HTTP, sc->connection->log, 0, + "spdy header block skip %uz of %uz", size, sc->length); + sc->zstream_in.next_in = pos; sc->zstream_in.avail_in = (size < sc->length) ? size : sc->length; @@ -1364,7 +1363,7 @@ ngx_http_spdy_state_window_update(ngx_ht ngx_log_error(NGX_LOG_INFO, sc->connection->log, 0, "client violated flow control for stream %ui: " "received WINDOW_UPDATE frame with delta %uz " - "that is not allowed for window %z", + "not allowed for window %z", sid, delta, stream->send_window); if (ngx_http_spdy_terminate_stream(sc, stream, @@ -1397,7 +1396,7 @@ ngx_http_spdy_state_window_update(ngx_ht ngx_log_error(NGX_LOG_INFO, sc->connection->log, 0, "client violated connection flow control: " "received WINDOW_UPDATE frame with delta %uz " - "that is not allowed for window %uz", + "not allowed for window %uz", delta, sc->send_window); return ngx_http_spdy_state_protocol_error(sc); @@ -1440,8 +1439,8 @@ ngx_http_spdy_state_data(ngx_http_spdy_c if (sc->length > sc->recv_window) { ngx_log_error(NGX_LOG_INFO, sc->connection->log, 0, - "client violated connection flow control: length of " - "received DATA frame %uz, while available window %uz", + "client violated connection flow control: " + "received DATA frame length %uz, available window %uz", sc->length, sc->recv_window); return ngx_http_spdy_state_protocol_error(sc); @@ -1465,13 +1464,16 @@ ngx_http_spdy_state_data(ngx_http_spdy_c stream = sc->stream; if (stream == NULL) { + ngx_log_debug0(NGX_LOG_DEBUG_HTTP, sc->connection->log, 0, + "unknown spdy stream"); + return ngx_http_spdy_state_skip(sc, pos, end); } if (sc->length > stream->recv_window) { ngx_log_error(NGX_LOG_INFO, sc->connection->log, 0, - "client violated flow control for stream %ui: length of " - "received DATA frame %uz, while available window %uz", + "client violated flow control for stream %ui: " + "received DATA frame length %uz, available window %uz", stream->id, sc->length, stream->recv_window); if (ngx_http_spdy_terminate_stream(sc, stream, @@ -1501,7 +1503,7 @@ ngx_http_spdy_state_data(ngx_http_spdy_c if (stream->in_closed) { ngx_log_error(NGX_LOG_INFO, sc->connection->log, 0, - "client sent DATA frame for half closed stream %ui", + "client sent DATA frame for half-closed stream %ui", stream->id); if (ngx_http_spdy_terminate_stream(sc, stream, @@ -1544,7 +1546,10 @@ ngx_http_spdy_state_read_data(ngx_http_s stream->in_closed = 1; } - /* TODO log and accounting */ + ngx_log_debug1(NGX_LOG_DEBUG_HTTP, sc->connection->log, 0, + "skipping spdy DATA frame, reason: %d", + stream->skip_data); + return ngx_http_spdy_state_skip(sc, pos, end); } @@ -1573,7 +1578,10 @@ ngx_http_spdy_state_read_data(ngx_http_s if (r->headers_in.content_length_n != -1 && r->headers_in.content_length_n < rb->rest) { - /* TODO logging */ + ngx_log_error(NGX_LOG_INFO, r->connection->log, 0, + "client intended to send body data " + "larger than declared"); + stream->skip_data = NGX_SPDY_DATA_ERROR; goto error; @@ -1584,9 +1592,8 @@ ngx_http_spdy_state_read_data(ngx_http_s && clcf->client_max_body_size < rb->rest) { ngx_log_error(NGX_LOG_ERR, r->connection->log, 0, - "client intended to send too large chunked " - "body: %O bytes", - rb->rest); + "client intended to send " + "too large chunked body: %O bytes", rb->rest); stream->skip_data = NGX_SPDY_DATA_ERROR; goto error; @@ -1638,7 +1645,7 @@ ngx_http_spdy_state_read_data(ngx_http_s } else if (r->headers_in.content_length_n != rb->rest) { ngx_log_error(NGX_LOG_INFO, r->connection->log, 0, "client prematurely closed stream: " - "%O of %O bytes of request body received", + "only %O out of %O bytes of request body received", rb->rest, r->headers_in.content_length_n); stream->skip_data = NGX_SPDY_DATA_ERROR; @@ -1717,9 +1724,11 @@ ngx_http_spdy_state_rst_stream(ngx_http_ "spdy RST_STREAM sid:%ui st:%ui", sid, status); stream = ngx_http_spdy_get_stream_by_id(sc, sid); + if (stream == NULL) { ngx_log_debug0(NGX_LOG_DEBUG_HTTP, sc->connection->log, 0, - "unknown stream, probably it has been closed already"); + "unknown spdy stream"); + return ngx_http_spdy_state_complete(sc, pos, end); } @@ -1738,7 +1747,7 @@ ngx_http_spdy_state_rst_stream(ngx_http_ case NGX_SPDY_INTERNAL_ERROR: ngx_log_error(NGX_LOG_INFO, fc->log, 0, - "client terminated stream %ui because of internal error", + "client terminated stream %ui due to internal error", sid); break; @@ -1770,7 +1779,10 @@ ngx_http_spdy_state_ping(ngx_http_spdy_c } if (sc->length != NGX_SPDY_PING_SIZE) { - /* TODO logging */ + ngx_log_error(NGX_LOG_INFO, sc->connection->log, 0, + "client sent PING frame with incorrect length %uz", + sc->length); + return ngx_http_spdy_state_protocol_error(sc); } @@ -1810,6 +1822,9 @@ ngx_http_spdy_state_skip(ngx_http_spdy_c size = end - pos; + ngx_log_debug2(NGX_LOG_DEBUG_HTTP, sc->connection->log, 0, + "spdy frame skip %uz of %uz", size, sc->length); + if (size < sc->length) { sc->length -= size; return ngx_http_spdy_state_save(sc, end, end, @@ -1839,13 +1854,16 @@ ngx_http_spdy_state_settings(ngx_http_sp ------------------------------ Message: 3 Date: Thu, 15 May 2014 15:25:53 +0000 From: Valentin Bartenev <vb...@nginx.com> To: nginx-devel@nginx.org Subject: [nginx] SPDY: refactored ngx_http_spdy_state_headers(). Message-ID: <hg.9a95eb9f448b.1400167553.6369085454036692...@ns.nginx.org> Content-Type: text/plain; charset="us-ascii" details: http://hg.nginx.org/nginx/rev/9a95eb9f448b branches: changeset: 5694:9a95eb9f448b user: Valentin Bartenev <vb...@nginx.com> date: Wed Apr 30 20:34:20 2014 +0400 description: SPDY: refactored ngx_http_spdy_state_headers(). This change is similar to d2ac5cf4056d. Special flag of completeness looks surplus when there is also a counter of frame bytes left. diffstat: src/http/ngx_http_spdy.c | 13 ++++--------- 1 files changed, 4 insertions(+), 9 deletions(-) diffs (52 lines): diff -r 701d6e17e42c -r 9a95eb9f448b src/http/ngx_http_spdy.c --- a/src/http/ngx_http_spdy.c Wed Apr 30 20:34:20 2014 +0400 +++ b/src/http/ngx_http_spdy.c Wed Apr 30 20:34:20 2014 +0400 @@ -1009,7 +1009,6 @@ ngx_http_spdy_state_headers(ngx_http_spd size_t size; ngx_buf_t *buf; ngx_int_t rc; - ngx_uint_t complete; ngx_http_request_t *r; size = end - pos; @@ -1019,12 +1018,8 @@ ngx_http_spdy_state_headers(ngx_http_spd ngx_http_spdy_state_headers); } - if (size >= sc->length) { + if (size > sc->length) { size = sc->length; - complete = 1; - - } else { - complete = 0; } r = sc->stream->request; @@ -1089,7 +1084,7 @@ ngx_http_spdy_state_headers(ngx_http_spd if (buf->last - buf->pos < NGX_SPDY_NV_NUM_SIZE) { - if (complete) { + if (sc->length == 0) { ngx_log_debug0(NGX_LOG_DEBUG_HTTP, r->connection->log, 0, "premature end of spdy header block"); @@ -1181,7 +1176,7 @@ ngx_http_spdy_state_headers(ngx_http_spd continue; } - if (complete) { + if (sc->length == 0) { ngx_log_debug0(NGX_LOG_DEBUG_HTTP, r->connection->log, 0, "premature end of spdy header block"); @@ -1225,7 +1220,7 @@ ngx_http_spdy_state_headers(ngx_http_spd return ngx_http_spdy_state_headers_error(sc, pos, end); } - if (!complete) { + if (sc->length) { return ngx_http_spdy_state_save(sc, pos, end, ngx_http_spdy_state_headers); } ------------------------------ Message: 4 Date: Thu, 15 May 2014 15:25:55 +0000 From: Valentin Bartenev <vb...@nginx.com> To: nginx-devel@nginx.org Subject: [nginx] SPDY: added a debug point to the state buffer overflow p... Message-ID: <hg.231588611230.1400167555.6369085454036692...@ns.nginx.org> Content-Type: text/plain; charset="us-ascii" details: http://hg.nginx.org/nginx/rev/231588611230 branches: changeset: 5695:231588611230 user: Valentin Bartenev <vb...@nginx.com> date: Wed Apr 30 20:34:20 2014 +0400 description: SPDY: added a debug point to the state buffer overflow protection. diffstat: src/http/ngx_http_spdy.c | 1 + 1 files changed, 1 insertions(+), 0 deletions(-) diffs (11 lines): diff -r 9a95eb9f448b -r 231588611230 src/http/ngx_http_spdy.c --- a/src/http/ngx_http_spdy.c Wed Apr 30 20:34:20 2014 +0400 +++ b/src/http/ngx_http_spdy.c Wed Apr 30 20:34:20 2014 +0400 @@ -1944,6 +1944,7 @@ ngx_http_spdy_state_save(ngx_http_spdy_c ngx_log_error(NGX_LOG_ALERT, sc->connection->log, 0, "state buffer overflow: %uz bytes required", size); + ngx_debug_point(); return ngx_http_spdy_state_internal_error(sc); } ------------------------------ Message: 5 Date: Thu, 15 May 2014 15:25:57 +0000 From: Valentin Bartenev <vb...@nginx.com> To: nginx-devel@nginx.org Subject: [nginx] SPDY: added protection from overrun of the receive buffer. Message-ID: <hg.19a14a484707.1400167557.6369085454036692...@ns.nginx.org> Content-Type: text/plain; charset="us-ascii" details: http://hg.nginx.org/nginx/rev/19a14a484707 branches: changeset: 5696:19a14a484707 user: Valentin Bartenev <vb...@nginx.com> date: Wed Apr 30 20:34:20 2014 +0400 description: SPDY: added protection from overrun of the receive buffer. diffstat: src/http/ngx_http_spdy.c | 8 ++++++++ 1 files changed, 8 insertions(+), 0 deletions(-) diffs (18 lines): diff -r 231588611230 -r 19a14a484707 src/http/ngx_http_spdy.c --- a/src/http/ngx_http_spdy.c Wed Apr 30 20:34:20 2014 +0400 +++ b/src/http/ngx_http_spdy.c Wed Apr 30 20:34:20 2014 +0400 @@ -1921,6 +1921,14 @@ ngx_http_spdy_state_complete(ngx_http_sp ngx_log_debug2(NGX_LOG_DEBUG_HTTP, sc->connection->log, 0, "spdy frame complete pos:%p end:%p", pos, end); + if (pos > end) { + ngx_log_error(NGX_LOG_ALERT, sc->connection->log, 0, + "receive buffer overrun"); + + ngx_debug_point(); + return ngx_http_spdy_state_internal_error(sc); + } + sc->handler = ngx_http_spdy_state_head; sc->stream = NULL; ------------------------------ _______________________________________________ nginx-devel mailing list nginx-devel@nginx.org http://mailman.nginx.org/mailman/listinfo/nginx-devel End of nginx-devel Digest, Vol 55, Issue 15 *******************************************
_______________________________________________ nginx-devel mailing list nginx-devel@nginx.org http://mailman.nginx.org/mailman/listinfo/nginx-devel