mirror/nginx
1
0
Fork 0
mirror of https://github.com/nginx/nginx.git synced 2025-06-08 02:02:38 +08:00
Code Issues Actions Packages Projects Releases Wiki Activity

SPDY: improved logging.

Browse Source
This commit is contained in:
Valentin Bartenev 2014-04-30 20:34:20 +04:00
parent d51d168066
commit d04a714a6d
2 changed files with 151 additions and 62 deletions
Show Stats Download Patch File Download Diff File Expand all files Collapse all files

210
src/http/ngx_http_spdy.c
View File

@ -395,8 +395,7 @@ ngx_http_spdy_init(ngx_event_t *rev)
c = rev->data; c = rev->data;
hc = c->data; hc = c->data;
ngx_log_debug0(NGX_LOG_DEBUG_HTTP, c->log, 0, ngx_log_debug0(NGX_LOG_DEBUG_HTTP, c->log, 0, "init spdy request");
"init spdy request");
c->log->action = "processing SPDY"; c->log->action = "processing SPDY";
@ -556,7 +555,7 @@ ngx_http_spdy_read_handler(ngx_event_t *rev)
if (n == 0 && (sc->incomplete || sc->processing)) { if (n == 0 && (sc->incomplete || sc->processing)) {
ngx_log_error(NGX_LOG_INFO, c->log, 0, ngx_log_error(NGX_LOG_INFO, c->log, 0,
"client closed prematurely connection"); "client prematurely closed connection");
} }
if (n == 0 || n == NGX_ERROR) { if (n == 0 || n == NGX_ERROR) {
@ -644,7 +643,7 @@ ngx_http_spdy_write_handler(ngx_event_t *wev)
stream->handled = 0; stream->handled = 0;
ngx_log_debug1(NGX_LOG_DEBUG_HTTP, c->log, 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 = stream->request->connection->write;
wev->handler(wev); wev->handler(wev);
@ -860,7 +859,7 @@ ngx_http_spdy_state_head(ngx_http_spdy_connection_t *sc, u_char *pos,
pos += sizeof(uint32_t); pos += sizeof(uint32_t);
ngx_log_debug3(NGX_LOG_DEBUG_HTTP, sc->connection->log, 0, 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); head, sc->flags, sc->length);
if (ngx_spdy_ctl_frame_check(head)) { if (ngx_spdy_ctl_frame_check(head)) {
@ -872,6 +871,8 @@ ngx_http_spdy_state_head(ngx_http_spdy_connection_t *sc, u_char *pos,
return ngx_http_spdy_state_syn_stream(sc, pos, end); return ngx_http_spdy_state_syn_stream(sc, pos, end);
case NGX_SPDY_SYN_REPLY: 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); return ngx_http_spdy_state_protocol_error(sc);
case NGX_SPDY_RST_STREAM: case NGX_SPDY_RST_STREAM:
@ -887,6 +888,8 @@ ngx_http_spdy_state_head(ngx_http_spdy_connection_t *sc, u_char *pos,
return ngx_http_spdy_state_skip(sc, pos, end); /* TODO */ return ngx_http_spdy_state_skip(sc, pos, end); /* TODO */
case NGX_SPDY_HEADERS: 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); return ngx_http_spdy_state_protocol_error(sc);
case NGX_SPDY_WINDOW_UPDATE: case NGX_SPDY_WINDOW_UPDATE:
@ -904,10 +907,8 @@ ngx_http_spdy_state_head(ngx_http_spdy_connection_t *sc, u_char *pos,
return ngx_http_spdy_state_data(sc, pos, end); return ngx_http_spdy_state_data(sc, pos, end);
} }
ngx_log_error(NGX_LOG_INFO, sc->connection->log, 0,
/* TODO version & type check */ "client sent invalid frame");
ngx_log_debug0(NGX_LOG_DEBUG_HTTP, sc->connection->log, 0,
"spdy unknown frame");
return ngx_http_spdy_state_protocol_error(sc); return ngx_http_spdy_state_protocol_error(sc);
} }
@ -927,7 +928,10 @@ ngx_http_spdy_state_syn_stream(ngx_http_spdy_connection_t *sc, u_char *pos,
} }
if (sc->length <= NGX_SPDY_SYN_STREAM_SIZE) { 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); return ngx_http_spdy_state_protocol_error(sc);
} }
@ -968,7 +972,7 @@ ngx_http_spdy_state_syn_stream(ngx_http_spdy_connection_t *sc, u_char *pos,
if (sc->processing >= sscf->concurrent_streams) { if (sc->processing >= sscf->concurrent_streams) {
ngx_log_error(NGX_LOG_INFO, sc->connection->log, 0, 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, if (ngx_http_spdy_send_rst_stream(sc, sid, NGX_SPDY_REFUSED_STREAM,
prio) prio)
@ -1026,7 +1030,7 @@ ngx_http_spdy_state_headers(ngx_http_spdy_connection_t *sc, u_char *pos,
r = sc->stream->request; r = sc->stream->request;
ngx_log_debug2(NGX_LOG_DEBUG_HTTP, r->connection->log, 0, 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; buf = r->header_in;
@ -1101,7 +1105,7 @@ ngx_http_spdy_state_headers(ngx_http_spdy_connection_t *sc, u_char *pos,
buf->pos += NGX_SPDY_NV_NUM_SIZE; buf->pos += NGX_SPDY_NV_NUM_SIZE;
ngx_log_debug1(NGX_LOG_DEBUG_HTTP, r->connection->log, 0, 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); sc->entries);
if (ngx_list_init(&r->headers_in.headers, r->pool, 20, if (ngx_list_init(&r->headers_in.headers, r->pool, 20,
@ -1142,7 +1146,6 @@ ngx_http_spdy_state_headers(ngx_http_spdy_connection_t *sc, u_char *pos,
rc = ngx_http_spdy_alloc_large_header_buffer(r); rc = ngx_http_spdy_alloc_large_header_buffer(r);
if (rc == NGX_DECLINED) { if (rc == NGX_DECLINED) {
/* TODO logging */
ngx_http_finalize_request(r, ngx_http_finalize_request(r,
NGX_HTTP_REQUEST_HEADER_TOO_LARGE); NGX_HTTP_REQUEST_HEADER_TOO_LARGE);
return ngx_http_spdy_state_headers_skip(sc, pos, end); return ngx_http_spdy_state_headers_skip(sc, pos, end);
@ -1179,9 +1182,8 @@ ngx_http_spdy_state_headers(ngx_http_spdy_connection_t *sc, u_char *pos,
} }
if (complete) { if (complete) {
/* TODO: improve error message */
ngx_log_debug0(NGX_LOG_DEBUG_HTTP, r->connection->log, 0, 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); return ngx_http_spdy_state_headers_error(sc, pos, end);
} }
@ -1190,13 +1192,7 @@ ngx_http_spdy_state_headers(ngx_http_spdy_connection_t *sc, u_char *pos,
ngx_http_spdy_state_headers); ngx_http_spdy_state_headers);
case NGX_HTTP_PARSE_INVALID_HEADER: 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); ngx_http_finalize_request(r, NGX_HTTP_BAD_REQUEST);
return ngx_http_spdy_state_headers_skip(sc, pos, end); return ngx_http_spdy_state_headers_skip(sc, pos, end);
default: /* NGX_ERROR */ default: /* NGX_ERROR */
@ -1262,6 +1258,9 @@ ngx_http_spdy_state_headers_skip(ngx_http_spdy_connection_t *sc, u_char *pos,
ngx_http_spdy_state_headers_skip); 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.next_in = pos;
sc->zstream_in.avail_in = (size < sc->length) ? size : sc->length; sc->zstream_in.avail_in = (size < sc->length) ? size : sc->length;
@ -1364,7 +1363,7 @@ ngx_http_spdy_state_window_update(ngx_http_spdy_connection_t *sc, u_char *pos,
ngx_log_error(NGX_LOG_INFO, sc->connection->log, 0, ngx_log_error(NGX_LOG_INFO, sc->connection->log, 0,
"client violated flow control for stream %ui: " "client violated flow control for stream %ui: "
"received WINDOW_UPDATE frame with delta %uz " "received WINDOW_UPDATE frame with delta %uz "
"that is not allowed for window %z", "not allowed for window %z",
sid, delta, stream->send_window); sid, delta, stream->send_window);
if (ngx_http_spdy_terminate_stream(sc, stream, if (ngx_http_spdy_terminate_stream(sc, stream,
@ -1397,7 +1396,7 @@ ngx_http_spdy_state_window_update(ngx_http_spdy_connection_t *sc, u_char *pos,
ngx_log_error(NGX_LOG_INFO, sc->connection->log, 0, ngx_log_error(NGX_LOG_INFO, sc->connection->log, 0,
"client violated connection flow control: " "client violated connection flow control: "
"received WINDOW_UPDATE frame with delta %uz " "received WINDOW_UPDATE frame with delta %uz "
"that is not allowed for window %uz", "not allowed for window %uz",
delta, sc->send_window); delta, sc->send_window);
return ngx_http_spdy_state_protocol_error(sc); return ngx_http_spdy_state_protocol_error(sc);
@ -1440,8 +1439,8 @@ ngx_http_spdy_state_data(ngx_http_spdy_connection_t *sc, u_char *pos,
if (sc->length > sc->recv_window) { if (sc->length > sc->recv_window) {
ngx_log_error(NGX_LOG_INFO, sc->connection->log, 0, ngx_log_error(NGX_LOG_INFO, sc->connection->log, 0,
"client violated connection flow control: length of " "client violated connection flow control: "
"received DATA frame %uz, while available window %uz", "received DATA frame length %uz, available window %uz",
sc->length, sc->recv_window); sc->length, sc->recv_window);
return ngx_http_spdy_state_protocol_error(sc); return ngx_http_spdy_state_protocol_error(sc);
@ -1465,13 +1464,16 @@ ngx_http_spdy_state_data(ngx_http_spdy_connection_t *sc, u_char *pos,
stream = sc->stream; stream = sc->stream;
if (stream == NULL) { 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); return ngx_http_spdy_state_skip(sc, pos, end);
} }
if (sc->length > stream->recv_window) { if (sc->length > stream->recv_window) {
ngx_log_error(NGX_LOG_INFO, sc->connection->log, 0, ngx_log_error(NGX_LOG_INFO, sc->connection->log, 0,
"client violated flow control for stream %ui: length of " "client violated flow control for stream %ui: "
"received DATA frame %uz, while available window %uz", "received DATA frame length %uz, available window %uz",
stream->id, sc->length, stream->recv_window); stream->id, sc->length, stream->recv_window);
if (ngx_http_spdy_terminate_stream(sc, stream, if (ngx_http_spdy_terminate_stream(sc, stream,
@ -1501,7 +1503,7 @@ ngx_http_spdy_state_data(ngx_http_spdy_connection_t *sc, u_char *pos,
if (stream->in_closed) { if (stream->in_closed) {
ngx_log_error(NGX_LOG_INFO, sc->connection->log, 0, 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); stream->id);
if (ngx_http_spdy_terminate_stream(sc, stream, if (ngx_http_spdy_terminate_stream(sc, stream,
@ -1544,7 +1546,10 @@ ngx_http_spdy_state_read_data(ngx_http_spdy_connection_t *sc, u_char *pos,
stream->in_closed = 1; 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); return ngx_http_spdy_state_skip(sc, pos, end);
} }
@ -1573,7 +1578,10 @@ ngx_http_spdy_state_read_data(ngx_http_spdy_connection_t *sc, u_char *pos,
if (r->headers_in.content_length_n != -1 if (r->headers_in.content_length_n != -1
&& r->headers_in.content_length_n < rb->rest) && 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; stream->skip_data = NGX_SPDY_DATA_ERROR;
goto error; goto error;
@ -1584,9 +1592,8 @@ ngx_http_spdy_state_read_data(ngx_http_spdy_connection_t *sc, u_char *pos,
&& clcf->client_max_body_size < rb->rest) && clcf->client_max_body_size < rb->rest)
{ {
ngx_log_error(NGX_LOG_ERR, r->connection->log, 0, ngx_log_error(NGX_LOG_ERR, r->connection->log, 0,
"client intended to send too large chunked " "client intended to send "
"body: %O bytes", "too large chunked body: %O bytes", rb->rest);
rb->rest);
stream->skip_data = NGX_SPDY_DATA_ERROR; stream->skip_data = NGX_SPDY_DATA_ERROR;
goto error; goto error;
@ -1638,7 +1645,7 @@ ngx_http_spdy_state_read_data(ngx_http_spdy_connection_t *sc, u_char *pos,
} else if (r->headers_in.content_length_n != rb->rest) { } else if (r->headers_in.content_length_n != rb->rest) {
ngx_log_error(NGX_LOG_INFO, r->connection->log, 0, ngx_log_error(NGX_LOG_INFO, r->connection->log, 0,
"client prematurely closed stream: " "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); rb->rest, r->headers_in.content_length_n);
stream->skip_data = NGX_SPDY_DATA_ERROR; stream->skip_data = NGX_SPDY_DATA_ERROR;
@ -1717,9 +1724,11 @@ ngx_http_spdy_state_rst_stream(ngx_http_spdy_connection_t *sc, u_char *pos,
"spdy RST_STREAM sid:%ui st:%ui", sid, status); "spdy RST_STREAM sid:%ui st:%ui", sid, status);
stream = ngx_http_spdy_get_stream_by_id(sc, sid); stream = ngx_http_spdy_get_stream_by_id(sc, sid);
if (stream == NULL) { if (stream == NULL) {
ngx_log_debug0(NGX_LOG_DEBUG_HTTP, sc->connection->log, 0, 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); return ngx_http_spdy_state_complete(sc, pos, end);
} }
@ -1738,7 +1747,7 @@ ngx_http_spdy_state_rst_stream(ngx_http_spdy_connection_t *sc, u_char *pos,
case NGX_SPDY_INTERNAL_ERROR: case NGX_SPDY_INTERNAL_ERROR:
ngx_log_error(NGX_LOG_INFO, fc->log, 0, 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); sid);
break; break;
@ -1770,7 +1779,10 @@ ngx_http_spdy_state_ping(ngx_http_spdy_connection_t *sc, u_char *pos,
} }
if (sc->length != NGX_SPDY_PING_SIZE) { 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); return ngx_http_spdy_state_protocol_error(sc);
} }
@ -1810,6 +1822,9 @@ ngx_http_spdy_state_skip(ngx_http_spdy_connection_t *sc, u_char *pos,
size = end - pos; 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) { if (size < sc->length) {
sc->length -= size; sc->length -= size;
return ngx_http_spdy_state_save(sc, end, end, return ngx_http_spdy_state_save(sc, end, end,
@ -1839,13 +1854,16 @@ ngx_http_spdy_state_settings(ngx_http_spdy_connection_t *sc, u_char *pos,
sc->length -= NGX_SPDY_SETTINGS_NUM_SIZE; sc->length -= NGX_SPDY_SETTINGS_NUM_SIZE;
if (sc->length < sc->entries * NGX_SPDY_SETTINGS_PAIR_SIZE) { if (sc->length < sc->entries * NGX_SPDY_SETTINGS_PAIR_SIZE) {
/* TODO logging */ ngx_log_error(NGX_LOG_INFO, sc->connection->log, 0,
"client sent SETTINGS frame with incorrect "
"length %uz or number of entries %ui",
sc->length, sc->entries);
return ngx_http_spdy_state_protocol_error(sc); return ngx_http_spdy_state_protocol_error(sc);
} }
ngx_log_debug1(NGX_LOG_DEBUG_HTTP, sc->connection->log, 0, ngx_log_debug1(NGX_LOG_DEBUG_HTTP, sc->connection->log, 0,
"spdy SETTINGS frame consists of %ui entries", "spdy SETTINGS frame has %ui entries", sc->entries);
sc->entries);
} }
while (sc->entries) { while (sc->entries) {
@ -1905,6 +1923,9 @@ static u_char *
ngx_http_spdy_state_complete(ngx_http_spdy_connection_t *sc, u_char *pos, ngx_http_spdy_state_complete(ngx_http_spdy_connection_t *sc, u_char *pos,
u_char *end) u_char *end)
{ {
ngx_log_debug2(NGX_LOG_DEBUG_HTTP, sc->connection->log, 0,
"spdy frame complete pos:%p end:%p", pos, end);
sc->handler = ngx_http_spdy_state_head; sc->handler = ngx_http_spdy_state_head;
sc->stream = NULL; sc->stream = NULL;
@ -1918,12 +1939,16 @@ ngx_http_spdy_state_save(ngx_http_spdy_connection_t *sc,
{ {
size_t size; size_t size;
ngx_log_debug3(NGX_LOG_DEBUG_HTTP, sc->connection->log, 0,
"spdy frame state save pos:%p end:%p handler:%p",
pos, end, handler);
size = end - pos; size = end - pos;
if (size > NGX_SPDY_STATE_BUFFER_SIZE) { if (size > NGX_SPDY_STATE_BUFFER_SIZE) {
ngx_log_error(NGX_LOG_ALERT, sc->connection->log, 0, ngx_log_error(NGX_LOG_ALERT, sc->connection->log, 0,
"spdy state buffer overflow: " "state buffer overflow: %uz bytes required", size);
"%uz bytes required", size);
return ngx_http_spdy_state_internal_error(sc); return ngx_http_spdy_state_internal_error(sc);
} }
@ -1998,7 +2023,7 @@ ngx_http_spdy_send_window_update(ngx_http_spdy_connection_t *sc, ngx_uint_t sid,
ngx_http_spdy_out_frame_t *frame; ngx_http_spdy_out_frame_t *frame;
ngx_log_debug2(NGX_LOG_DEBUG_HTTP, sc->connection->log, 0, ngx_log_debug2(NGX_LOG_DEBUG_HTTP, sc->connection->log, 0,
"spdy write WINDOW_UPDATE sid:%ui delta:%ui", sid, delta); "spdy send WINDOW_UPDATE sid:%ui delta:%ui", sid, delta);
frame = ngx_http_spdy_get_ctl_frame(sc, NGX_SPDY_WINDOW_UPDATE_SIZE, frame = ngx_http_spdy_get_ctl_frame(sc, NGX_SPDY_WINDOW_UPDATE_SIZE,
NGX_SPDY_HIGHEST_PRIORITY); NGX_SPDY_HIGHEST_PRIORITY);
@ -2037,7 +2062,7 @@ ngx_http_spdy_send_rst_stream(ngx_http_spdy_connection_t *sc, ngx_uint_t sid,
} }
ngx_log_debug2(NGX_LOG_DEBUG_HTTP, sc->connection->log, 0, ngx_log_debug2(NGX_LOG_DEBUG_HTTP, sc->connection->log, 0,
"spdy write RST_STREAM sid:%ui st:%ui", sid, status); "spdy send RST_STREAM sid:%ui st:%ui", sid, status);
frame = ngx_http_spdy_get_ctl_frame(sc, NGX_SPDY_RST_STREAM_SIZE, frame = ngx_http_spdy_get_ctl_frame(sc, NGX_SPDY_RST_STREAM_SIZE,
priority); priority);
@ -2072,7 +2097,7 @@ ngx_http_spdy_send_goaway(ngx_http_spdy_connection_t *sc)
ngx_http_spdy_out_frame_t *frame; ngx_http_spdy_out_frame_t *frame;
ngx_log_debug1(NGX_LOG_DEBUG_HTTP, sc->connection->log, 0, ngx_log_debug1(NGX_LOG_DEBUG_HTTP, sc->connection->log, 0,
"spdy create GOAWAY sid:%ui", sc->last_sid); "spdy send GOAWAY sid:%ui", sc->last_sid);
frame = ngx_http_spdy_get_ctl_frame(sc, NGX_SPDY_GOAWAY_SIZE, frame = ngx_http_spdy_get_ctl_frame(sc, NGX_SPDY_GOAWAY_SIZE,
NGX_SPDY_HIGHEST_PRIORITY); NGX_SPDY_HIGHEST_PRIORITY);
@ -2108,7 +2133,7 @@ ngx_http_spdy_send_settings(ngx_http_spdy_connection_t *sc)
ngx_http_spdy_out_frame_t *frame; ngx_http_spdy_out_frame_t *frame;
ngx_log_debug0(NGX_LOG_DEBUG_HTTP, sc->connection->log, 0, ngx_log_debug0(NGX_LOG_DEBUG_HTTP, sc->connection->log, 0,
"spdy create SETTINGS frame"); "spdy send SETTINGS frame");
frame = ngx_palloc(sc->pool, sizeof(ngx_http_spdy_out_frame_t)); frame = ngx_palloc(sc->pool, sizeof(ngx_http_spdy_out_frame_t));
if (frame == NULL) { if (frame == NULL) {
@ -2230,7 +2255,7 @@ ngx_http_spdy_get_ctl_frame(ngx_http_spdy_connection_t *sc, size_t length,
#if (NGX_DEBUG) #if (NGX_DEBUG)
if (length > NGX_SPDY_CTL_FRAME_BUFFER_SIZE - NGX_SPDY_FRAME_HEADER_SIZE) { if (length > NGX_SPDY_CTL_FRAME_BUFFER_SIZE - NGX_SPDY_FRAME_HEADER_SIZE) {
ngx_log_error(NGX_LOG_ALERT, sc->pool->log, 0, ngx_log_error(NGX_LOG_ALERT, sc->pool->log, 0,
"requested control frame is too big: %uz", length); "requested control frame is too large: %uz", length);
return NULL; return NULL;
} }
@ -2498,6 +2523,10 @@ ngx_http_spdy_parse_header(ngx_http_request_t *r)
case LF: case LF:
case CR: case CR:
case ':': case ':':
ngx_log_error(NGX_LOG_INFO, r->connection->log, 0,
"client sent invalid header name: \"%*s\"",
r->lowcase_index, r->header_name_start);
return NGX_HTTP_PARSE_INVALID_HEADER; return NGX_HTTP_PARSE_INVALID_HEADER;
} }
@ -2555,6 +2584,15 @@ ngx_http_spdy_parse_header(ngx_http_request_t *r)
} }
if (ch == CR || ch == LF) { if (ch == CR || ch == LF) {
ngx_log_error(NGX_LOG_INFO, r->connection->log, 0,
"client sent header \"%*s\" with "
"invalid value: \"%*s\\%c...\"",
r->header_name_end - r->header_name_start,
r->header_name_start,
p - r->header_start,
r->header_start,
ch == CR ? 'r' : 'n');
return NGX_HTTP_PARSE_INVALID_HEADER; return NGX_HTTP_PARSE_INVALID_HEADER;
} }
@ -2579,7 +2617,7 @@ ngx_http_spdy_parse_header(ngx_http_request_t *r)
static ngx_int_t static ngx_int_t
ngx_http_spdy_alloc_large_header_buffer(ngx_http_request_t *r) ngx_http_spdy_alloc_large_header_buffer(ngx_http_request_t *r)
{ {
u_char *old, *new; u_char *old, *new, *p;
size_t rest; size_t rest;
ngx_buf_t *buf; ngx_buf_t *buf;
ngx_http_spdy_stream_t *stream; ngx_http_spdy_stream_t *stream;
@ -2595,12 +2633,30 @@ ngx_http_spdy_alloc_large_header_buffer(ngx_http_request_t *r)
if (stream->header_buffers if (stream->header_buffers
== (ngx_uint_t) cscf->large_client_header_buffers.num) == (ngx_uint_t) cscf->large_client_header_buffers.num)
{ {
ngx_log_error(NGX_LOG_INFO, r->connection->log, 0,
"client sent too large request");
return NGX_DECLINED; return NGX_DECLINED;
} }
rest = r->header_in->last - r->header_in->pos; rest = r->header_in->last - r->header_in->pos;
/*
* equality is prohibited since one more byte is needed
* for null-termination
*/
if (rest >= cscf->large_client_header_buffers.size) { if (rest >= cscf->large_client_header_buffers.size) {
p = r->header_in->pos;
if (rest > NGX_MAX_ERROR_STR - 300) {
rest = NGX_MAX_ERROR_STR - 300;
p[rest++] = '.'; p[rest++] = '.'; p[rest++] = '.';
}
ngx_log_error(NGX_LOG_INFO, r->connection->log, 0,
"client sent too long header name or value: \"%*s\"",
rest, p);
return NGX_DECLINED; return NGX_DECLINED;
} }
@ -2610,7 +2666,7 @@ ngx_http_spdy_alloc_large_header_buffer(ngx_http_request_t *r)
} }
ngx_log_debug2(NGX_LOG_DEBUG_HTTP, r->connection->log, 0, ngx_log_debug2(NGX_LOG_DEBUG_HTTP, r->connection->log, 0,
"spdy large header alloc: %p %z", "spdy large header alloc: %p %uz",
buf->pos, buf->end - buf->last); buf->pos, buf->end - buf->last);
old = r->header_in->pos; old = r->header_in->pos;
@ -2665,6 +2721,11 @@ ngx_http_spdy_handle_request_header(ngx_http_request_t *r)
return sh->handler(r); return sh->handler(r);
} }
ngx_log_error(NGX_LOG_INFO, r->connection->log, 0,
"client sent invalid header name: \":%*s\"",
r->header_end - r->header_name_start,
r->header_name_start);
return NGX_HTTP_PARSE_INVALID_HEADER; return NGX_HTTP_PARSE_INVALID_HEADER;
} }
@ -2735,6 +2796,9 @@ ngx_http_spdy_parse_method(ngx_http_request_t *r)
}, *test; }, *test;
if (r->method_name.len) { if (r->method_name.len) {
ngx_log_error(NGX_LOG_INFO, r->connection->log, 0,
"client sent duplicate :method header");
return NGX_HTTP_PARSE_INVALID_HEADER; return NGX_HTTP_PARSE_INVALID_HEADER;
} }
@ -2772,7 +2836,9 @@ ngx_http_spdy_parse_method(ngx_http_request_t *r)
do { do {
if ((*p < 'A' || *p > 'Z') && *p != '_') { if ((*p < 'A' || *p > 'Z') && *p != '_') {
ngx_log_error(NGX_LOG_INFO, r->connection->log, 0, ngx_log_error(NGX_LOG_INFO, r->connection->log, 0,
"client sent invalid method"); "client sent invalid method: \"%V\"",
&r->method_name);
return NGX_HTTP_PARSE_INVALID_HEADER; return NGX_HTTP_PARSE_INVALID_HEADER;
} }
@ -2788,6 +2854,9 @@ static ngx_int_t
ngx_http_spdy_parse_scheme(ngx_http_request_t *r) ngx_http_spdy_parse_scheme(ngx_http_request_t *r)
{ {
if (r->schema_start) { if (r->schema_start) {
ngx_log_error(NGX_LOG_INFO, r->connection->log, 0,
"client sent duplicate :schema header");
return NGX_HTTP_PARSE_INVALID_HEADER; return NGX_HTTP_PARSE_INVALID_HEADER;
} }
@ -2804,6 +2873,9 @@ ngx_http_spdy_parse_host(ngx_http_request_t *r)
ngx_table_elt_t *h; ngx_table_elt_t *h;
if (r->headers_in.host) { if (r->headers_in.host) {
ngx_log_error(NGX_LOG_INFO, r->connection->log, 0,
"client sent duplicate :host header");
return NGX_HTTP_PARSE_INVALID_HEADER; return NGX_HTTP_PARSE_INVALID_HEADER;
} }
@ -2832,6 +2904,9 @@ static ngx_int_t
ngx_http_spdy_parse_path(ngx_http_request_t *r) ngx_http_spdy_parse_path(ngx_http_request_t *r)
{ {
if (r->unparsed_uri.len) { if (r->unparsed_uri.len) {
ngx_log_error(NGX_LOG_INFO, r->connection->log, 0,
"client sent duplicate :path header");
return NGX_HTTP_PARSE_INVALID_HEADER; return NGX_HTTP_PARSE_INVALID_HEADER;
} }
@ -2839,6 +2914,10 @@ ngx_http_spdy_parse_path(ngx_http_request_t *r)
r->uri_end = r->header_end; r->uri_end = r->header_end;
if (ngx_http_parse_uri(r) != NGX_OK) { if (ngx_http_parse_uri(r) != NGX_OK) {
ngx_log_error(NGX_LOG_INFO, r->connection->log, 0,
"client sent invalid URI: \"%*s\"",
r->uri_end - r->uri_start, r->uri_start);
return NGX_HTTP_PARSE_INVALID_HEADER; return NGX_HTTP_PARSE_INVALID_HEADER;
} }
@ -2860,19 +2939,22 @@ ngx_http_spdy_parse_version(ngx_http_request_t *r)
u_char *p, ch; u_char *p, ch;
if (r->http_protocol.len) { if (r->http_protocol.len) {
ngx_log_error(NGX_LOG_INFO, r->connection->log, 0,
"client sent duplicate :version header");
return NGX_HTTP_PARSE_INVALID_HEADER; return NGX_HTTP_PARSE_INVALID_HEADER;
} }
p = r->header_start; p = r->header_start;
if (r->header_end - p < 8 || !(ngx_str5cmp(p, 'H', 'T', 'T', 'P', '/'))) { if (r->header_end - p < 8 || !(ngx_str5cmp(p, 'H', 'T', 'T', 'P', '/'))) {
return NGX_HTTP_PARSE_INVALID_HEADER; goto invalid;
} }
ch = *(p + 5); ch = *(p + 5);
if (ch < '1' || ch > '9') { if (ch < '1' || ch > '9') {
return NGX_HTTP_PARSE_INVALID_HEADER; goto invalid;
} }
r->http_major = ch - '0'; r->http_major = ch - '0';
@ -2886,20 +2968,20 @@ ngx_http_spdy_parse_version(ngx_http_request_t *r)
} }
if (ch < '0' || ch > '9') { if (ch < '0' || ch > '9') {
return NGX_HTTP_PARSE_INVALID_HEADER; goto invalid;
} }
r->http_major = r->http_major * 10 + ch - '0'; r->http_major = r->http_major * 10 + ch - '0';
} }
if (*p != '.') { if (*p != '.') {
return NGX_HTTP_PARSE_INVALID_HEADER; goto invalid;
} }
ch = *(p + 1); ch = *(p + 1);
if (ch < '0' || ch > '9') { if (ch < '0' || ch > '9') {
return NGX_HTTP_PARSE_INVALID_HEADER; goto invalid;
} }
r->http_minor = ch - '0'; r->http_minor = ch - '0';
@ -2909,7 +2991,7 @@ ngx_http_spdy_parse_version(ngx_http_request_t *r)
ch = *p; ch = *p;
if (ch < '0' || ch > '9') { if (ch < '0' || ch > '9') {
return NGX_HTTP_PARSE_INVALID_HEADER; goto invalid;
} }
r->http_minor = r->http_minor * 10 + ch - '0'; r->http_minor = r->http_minor * 10 + ch - '0';
@ -2920,6 +3002,14 @@ ngx_http_spdy_parse_version(ngx_http_request_t *r)
r->http_version = r->http_major * 1000 + r->http_minor; r->http_version = r->http_major * 1000 + r->http_minor;
return NGX_OK; return NGX_OK;
invalid:
ngx_log_error(NGX_LOG_INFO, r->connection->log, 0,
"client sent invalid http version: \"%*s\"",
r->header_end - r->header_start, r->header_start);
return NGX_HTTP_PARSE_INVALID_HEADER;
} }
@ -3007,7 +3097,7 @@ ngx_http_spdy_run_request(ngx_http_request_t *r)
} }
ngx_log_debug2(NGX_LOG_DEBUG_HTTP, r->connection->log, 0, ngx_log_debug2(NGX_LOG_DEBUG_HTTP, r->connection->log, 0,
"http header: \"%V: %V\"", &h[i].key, &h[i].value); "spdy http header: \"%V: %V\"", &h[i].key, &h[i].value);
} }
r->http_state = NGX_HTTP_PROCESS_REQUEST_STATE; r->http_state = NGX_HTTP_PROCESS_REQUEST_STATE;
@ -3269,7 +3359,7 @@ ngx_http_spdy_close_stream(ngx_http_spdy_stream_t *stream, ngx_int_t rc)
if (ev->active || ev->disabled) { if (ev->active || ev->disabled) {
ngx_log_error(NGX_LOG_ALERT, sc->connection->log, 0, ngx_log_error(NGX_LOG_ALERT, sc->connection->log, 0,
"spdy fake read event was activated"); "fake read event was activated");
} }
if (ev->timer_set) { if (ev->timer_set) {
@ -3284,7 +3374,7 @@ ngx_http_spdy_close_stream(ngx_http_spdy_stream_t *stream, ngx_int_t rc)
if (ev->active || ev->disabled) { if (ev->active || ev->disabled) {
ngx_log_error(NGX_LOG_ALERT, sc->connection->log, 0, ngx_log_error(NGX_LOG_ALERT, sc->connection->log, 0,
"spdy fake write event was activated"); "fake write event was activated");
} }
if (ev->timer_set) { if (ev->timer_set) {

3
src/http/ngx_http_spdy_filter_module.c
View File

@ -533,8 +533,7 @@ ngx_http_spdy_header_filter(ngx_http_request_t *r)
ngx_free(buf); ngx_free(buf);
if (rc != Z_OK) { if (rc != Z_OK) {
ngx_log_error(NGX_LOG_ALERT, c->log, 0, ngx_log_error(NGX_LOG_ALERT, c->log, 0, "deflate() failed: %d", rc);
"spdy deflate() failed: %d", rc);
return NGX_ERROR; return NGX_ERROR;
} }