Mercurial > hg > nginx

changeset 5693:701d6e17e42c

Find changesets by keywords (author, files, the commit message), revision number or hash, or revset expression.
SPDY: improved logging.
author Valentin Bartenev <vbart@nginx.com>
date Wed, 30 Apr 2014 20:34:20 +0400
parents ed5fb7d22d46
children 9a95eb9f448b
files src/http/ngx_http_spdy.c src/http/ngx_http_spdy_filter_module.c
diffstat 2 files changed, 151 insertions(+), 62 deletions(-) [+]
line wrap: on
line diff
--- a/src/http/ngx_http_spdy.c
+++ b/src/http/ngx_http_spdy.c
@@ -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
         sc->length -= NGX_SPDY_SETTINGS_NUM_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);
         }
 
         ngx_log_debug1(NGX_LOG_DEBUG_HTTP, sc->connection->log, 0,
-                       "spdy SETTINGS frame consists of %ui entries",
-                       sc->entries);
+                       "spdy SETTINGS frame has %ui entries", 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,
     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->stream = NULL;
 
@@ -1918,12 +1939,16 @@ ngx_http_spdy_state_save(ngx_http_spdy_c
 {
     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;
 
     if (size > NGX_SPDY_STATE_BUFFER_SIZE) {
         ngx_log_error(NGX_LOG_ALERT, sc->connection->log, 0,
-                      "spdy state buffer overflow: "
-                      "%uz bytes required", size);
+                      "state buffer overflow: %uz bytes required", size);
+
         return ngx_http_spdy_state_internal_error(sc);
     }
 
@@ -1998,7 +2023,7 @@ ngx_http_spdy_send_window_update(ngx_htt
     ngx_http_spdy_out_frame_t  *frame;
 
     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,
                                         NGX_SPDY_HIGHEST_PRIORITY);
@@ -2037,7 +2062,7 @@ ngx_http_spdy_send_rst_stream(ngx_http_s
     }
 
     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,
                                         priority);
@@ -2072,7 +2097,7 @@ ngx_http_spdy_send_goaway(ngx_http_spdy_
     ngx_http_spdy_out_frame_t  *frame;
 
     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,
                                         NGX_SPDY_HIGHEST_PRIORITY);
@@ -2108,7 +2133,7 @@ ngx_http_spdy_send_settings(ngx_http_spd
     ngx_http_spdy_out_frame_t  *frame;
 
     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));
     if (frame == NULL) {
@@ -2230,7 +2255,7 @@ ngx_http_spdy_get_ctl_frame(ngx_http_spd
 #if (NGX_DEBUG)
     if (length > NGX_SPDY_CTL_FRAME_BUFFER_SIZE - NGX_SPDY_FRAME_HEADER_SIZE) {
         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;
     }
 
@@ -2498,6 +2523,10 @@ ngx_http_spdy_parse_header(ngx_http_requ
             case LF:
             case CR:
             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;
             }
 
@@ -2555,6 +2584,15 @@ ngx_http_spdy_parse_header(ngx_http_requ
             }
 
             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;
             }
 
@@ -2579,7 +2617,7 @@ ngx_http_spdy_parse_header(ngx_http_requ
 static ngx_int_t
 ngx_http_spdy_alloc_large_header_buffer(ngx_http_request_t *r)
 {
-    u_char                    *old, *new;
+    u_char                    *old, *new, *p;
     size_t                     rest;
     ngx_buf_t                 *buf;
     ngx_http_spdy_stream_t    *stream;
@@ -2595,12 +2633,30 @@ ngx_http_spdy_alloc_large_header_buffer(
     if (stream->header_buffers
         == (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;
     }
 
     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) {
+        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;
     }
 
@@ -2610,7 +2666,7 @@ ngx_http_spdy_alloc_large_header_buffer(
     }
 
     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);
 
     old = r->header_in->pos;
@@ -2665,6 +2721,11 @@ ngx_http_spdy_handle_request_header(ngx_
             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;
     }
 
@@ -2735,6 +2796,9 @@ ngx_http_spdy_parse_method(ngx_http_requ
     }, *test;
 
     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;
     }
 
@@ -2772,7 +2836,9 @@ ngx_http_spdy_parse_method(ngx_http_requ
     do {
         if ((*p < 'A' || *p > 'Z') && *p != '_') {
             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;
         }
 
@@ -2788,6 +2854,9 @@ static ngx_int_t
 ngx_http_spdy_parse_scheme(ngx_http_request_t *r)
 {
     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;
     }
 
@@ -2804,6 +2873,9 @@ ngx_http_spdy_parse_host(ngx_http_reques
     ngx_table_elt_t  *h;
 
     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;
     }
 
@@ -2832,6 +2904,9 @@ static ngx_int_t
 ngx_http_spdy_parse_path(ngx_http_request_t *r)
 {
     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;
     }
 
@@ -2839,6 +2914,10 @@ ngx_http_spdy_parse_path(ngx_http_reques
     r->uri_end = r->header_end;
 
     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;
     }
 
@@ -2860,19 +2939,22 @@ ngx_http_spdy_parse_version(ngx_http_req
     u_char  *p, ch;
 
     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;
     }
 
     p = r->header_start;
 
     if (r->header_end - p < 8 || !(ngx_str5cmp(p, 'H', 'T', 'T', 'P', '/'))) {
-        return NGX_HTTP_PARSE_INVALID_HEADER;
+        goto invalid;
     }
 
     ch = *(p + 5);
 
     if (ch < '1' || ch > '9') {
-        return NGX_HTTP_PARSE_INVALID_HEADER;
+        goto invalid;
     }
 
     r->http_major = ch - '0';
@@ -2886,20 +2968,20 @@ ngx_http_spdy_parse_version(ngx_http_req
         }
 
         if (ch < '0' || ch > '9') {
-            return NGX_HTTP_PARSE_INVALID_HEADER;
+            goto invalid;
         }
 
         r->http_major = r->http_major * 10 + ch - '0';
     }
 
     if (*p != '.') {
-        return NGX_HTTP_PARSE_INVALID_HEADER;
+        goto invalid;
     }
 
     ch = *(p + 1);
 
     if (ch < '0' || ch > '9') {
-        return NGX_HTTP_PARSE_INVALID_HEADER;
+        goto invalid;
     }
 
     r->http_minor = ch - '0';
@@ -2909,7 +2991,7 @@ ngx_http_spdy_parse_version(ngx_http_req
         ch = *p;
 
         if (ch < '0' || ch > '9') {
-            return NGX_HTTP_PARSE_INVALID_HEADER;
+            goto invalid;
         }
 
         r->http_minor = r->http_minor * 10 + ch - '0';
@@ -2920,6 +3002,14 @@ ngx_http_spdy_parse_version(ngx_http_req
     r->http_version = r->http_major * 1000 + r->http_minor;
 
     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_reque
         }
 
         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;
@@ -3269,7 +3359,7 @@ ngx_http_spdy_close_stream(ngx_http_spdy
 
     if (ev->active || ev->disabled) {
         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) {
@@ -3284,7 +3374,7 @@ ngx_http_spdy_close_stream(ngx_http_spdy
 
     if (ev->active || ev->disabled) {
         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) {
--- a/src/http/ngx_http_spdy_filter_module.c
+++ b/src/http/ngx_http_spdy_filter_module.c
@@ -533,8 +533,7 @@ ngx_http_spdy_header_filter(ngx_http_req
     ngx_free(buf);
 
     if (rc != Z_OK) {
-        ngx_log_error(NGX_LOG_ALERT, c->log, 0,
-                      "spdy deflate() failed: %d", rc);
+        ngx_log_error(NGX_LOG_ALERT, c->log, 0, "deflate() failed: %d", rc);
         return NGX_ERROR;
     }