From d0fbbe6932518ef38152ca691b08b5997a615c21 Mon Sep 17 00:00:00 2001 From: Tatsuhiro Tsujikawa Date: Thu, 20 Mar 2014 00:27:39 +0900 Subject: [PATCH] Less cryptic debug message --- lib/nghttp2_frame.c | 26 ++++---- lib/nghttp2_hd.c | 126 ++++++++++++++++++++++++++--------- lib/nghttp2_session.c | 150 +++++++++++++++++++++++++----------------- 3 files changed, 199 insertions(+), 103 deletions(-) diff --git a/lib/nghttp2_frame.c b/lib/nghttp2_frame.c index f9003289..7794df70 100644 --- a/lib/nghttp2_frame.c +++ b/lib/nghttp2_frame.c @@ -245,7 +245,8 @@ static int frame_pack_headers_shared(nghttp2_bufs *bufs, hd = *frame_hd; hd.length = nghttp2_buf_len(buf); - DEBUGF(fprintf(stderr, "HEADERS/PUSH_PROMISE, payloadlen=%zu\n", hd.length)); + DEBUGF(fprintf(stderr, + "send: HEADERS/PUSH_PROMISE, payloadlen=%zu\n", hd.length)); /* We have multiple frame buffers, which means one or more CONTINUATION frame is involved. Remove END_HEADERS flag from the @@ -270,7 +271,8 @@ static int frame_pack_headers_shared(nghttp2_bufs *bufs, hd.length = nghttp2_buf_len(buf); - DEBUGF(fprintf(stderr, "int CONTINUATION, payloadlen=%zu\n", hd.length)); + DEBUGF(fprintf(stderr, + "send: int CONTINUATION, payloadlen=%zu\n", hd.length)); buf->pos -= NGHTTP2_FRAME_HDLEN; nghttp2_frame_pack_frame_hd(buf->pos, &hd); @@ -281,7 +283,8 @@ static int frame_pack_headers_shared(nghttp2_bufs *bufs, /* Set END_HEADERS flag for last CONTINUATION */ hd.flags = NGHTTP2_FLAG_END_HEADERS; - DEBUGF(fprintf(stderr, "last CONTINUATION, payloadlen=%zu\n", hd.length)); + DEBUGF(fprintf(stderr, + "send: last CONTINUATION, payloadlen=%zu\n", hd.length)); buf->pos -= NGHTTP2_FRAME_HDLEN; nghttp2_frame_pack_frame_hd(buf->pos, &hd); @@ -731,7 +734,7 @@ static void frame_set_pad(nghttp2_buf *buf, size_t padlen) size_t trail_padlen; if(padlen > 256) { - DEBUGF(fprintf(stderr, "padlen=%zu, shift left 2 bytes\n", padlen)); + DEBUGF(fprintf(stderr, "send: padlen=%zu, shift left 2 bytes\n", padlen)); memmove(buf->pos - 2, buf->pos, NGHTTP2_FRAME_HDLEN); @@ -746,7 +749,7 @@ static void frame_set_pad(nghttp2_buf *buf, size_t padlen) buf->pos[NGHTTP2_FRAME_HDLEN + 1] = trail_padlen & 0xff; } else if(padlen > 0) { - DEBUGF(fprintf(stderr, "padlen=%zu, shift left 1 bytes\n", padlen)); + DEBUGF(fprintf(stderr, "send: padlen=%zu, shift left 1 bytes\n", padlen)); memmove(buf->pos - 1, buf->pos, NGHTTP2_FRAME_HDLEN); @@ -760,7 +763,7 @@ static void frame_set_pad(nghttp2_buf *buf, size_t padlen) buf->pos[NGHTTP2_FRAME_HDLEN] = trail_padlen; } else { - DEBUGF(fprintf(stderr, "padlen=0, no shift left was made\n")); + DEBUGF(fprintf(stderr, "send: padlen=0, no shift left was made\n")); return; } @@ -784,7 +787,7 @@ int nghttp2_frame_add_pad(nghttp2_bufs *bufs, nghttp2_frame_hd *hd, nghttp2_frame_hd last_hd; if(padlen == 0) { - DEBUGF(fprintf(stderr, "padlen = 0, nothing to do\n")); + DEBUGF(fprintf(stderr, "send: padlen = 0, nothing to do\n")); return 0; } @@ -817,7 +820,7 @@ int nghttp2_frame_add_pad(nghttp2_bufs *bufs, nghttp2_frame_hd *hd, if(last_avail >= padlen) { /* Last frame can include all paddings bytes */ - DEBUGF(fprintf(stderr, "last frame includes all paddings\n")); + DEBUGF(fprintf(stderr, "send: last frame includes all paddings\n")); frame_set_pad(buf, padlen); @@ -846,9 +849,10 @@ int nghttp2_frame_add_pad(nghttp2_bufs *bufs, nghttp2_frame_hd *hd, /* former last frame may have zero buffer available */ if(trail_padlen == 0) { - DEBUGF(fprintf(stderr, "last frame has no space to include padding\n")); + DEBUGF(fprintf(stderr, + "send: last frame has no space to include padding\n")); } else { - DEBUGF(fprintf(stderr, "padding across 2 frames\n")); + DEBUGF(fprintf(stderr, "send: padding across 2 frames\n")); frame_set_pad(buf, trail_padlen); } @@ -876,7 +880,7 @@ int nghttp2_frame_add_pad(nghttp2_bufs *bufs, nghttp2_frame_hd *hd, hd->length += padlen; - DEBUGF(fprintf(stderr, "final payloadlen=%zu, padlen=%zu\n", + DEBUGF(fprintf(stderr, "send: final payloadlen=%zu, padlen=%zu\n", hd->length, padlen)); return 0; diff --git a/lib/nghttp2_hd.c b/lib/nghttp2_hd.c index 79c0e12d..4d42e783 100644 --- a/lib/nghttp2_hd.c +++ b/lib/nghttp2_hd.c @@ -397,7 +397,7 @@ static size_t entry_room(size_t namelen, size_t valuelen) static int emit_indexed_header(nghttp2_nv *nv_out, nghttp2_hd_entry *ent) { - DEBUGF(fprintf(stderr, "Header emission:\n")); + DEBUGF(fprintf(stderr, "inflatehd: header emission: ")); DEBUGF(fwrite(ent->nv.name, ent->nv.namelen, 1, stderr)); DEBUGF(fprintf(stderr, ": ")); DEBUGF(fwrite(ent->nv.value, ent->nv.valuelen, 1, stderr)); @@ -412,7 +412,7 @@ static int emit_indexed_header(nghttp2_nv *nv_out, nghttp2_hd_entry *ent) static int emit_literal_header(nghttp2_nv *nv_out, nghttp2_nv *nv) { - DEBUGF(fprintf(stderr, "Header emission:\n")); + DEBUGF(fprintf(stderr, "inflatehd: header emission: ")); DEBUGF(fwrite(nv->name, nv->namelen, 1, stderr)); DEBUGF(fprintf(stderr, ": ")); DEBUGF(fwrite(nv->value, nv->valuelen, 1, stderr)); @@ -540,6 +540,8 @@ static int emit_clear_refset(nghttp2_bufs *bufs) int rv; uint8_t sb[] = {0x80u, 0x80u}; + DEBUGF(fprintf(stderr, "deflatehd: emit clear refset\n")); + rv = nghttp2_bufs_add(bufs, sb, sizeof(sb)); if(rv != 0) { return nghttp2_hd_handle_buffer_error(rv); @@ -555,14 +557,14 @@ static int emit_table_size(nghttp2_bufs *bufs, size_t table_size) size_t blocklen; uint8_t sb[16]; + DEBUGF(fprintf(stderr, "deflatehd: emit table_size=%zu\n", table_size)); + blocklen = 1 + count_encoded_length(table_size, 7); if(sizeof(sb) < blocklen) { return NGHTTP2_ERR_HEADER_COMP; } - DEBUGF(fprintf(stderr, "emit table_size=%zu\n", table_size)); - bufp = sb; *bufp++ = 0x80u; @@ -586,6 +588,9 @@ static int emit_indexed_block(nghttp2_bufs *bufs, size_t index) blocklen = count_encoded_length(index + 1, 7); + DEBUGF(fprintf(stderr, "deflatehd: emit indexed index=%zu, %zu bytes\n", + index, blocklen)); + if(sizeof(sb) < blocklen) { return NGHTTP2_ERR_HEADER_COMP; } @@ -613,6 +618,12 @@ static int emit_string(nghttp2_bufs *bufs, blocklen = count_encoded_length(enclen, 7); + DEBUGF(fprintf(stderr, + "deflatehd: emit string str=")); + DEBUGF(fwrite(str, len, 1, stderr)); + DEBUGF(fprintf(stderr, ", length=%zu, huffman=%d, encoded_length=%zu\n", + len, huffman, enclen)); + if(sizeof(sb) < blocklen) { return NGHTTP2_ERR_HEADER_COMP; } @@ -647,6 +658,11 @@ static int emit_indname_block(nghttp2_bufs *bufs, size_t index, int huffman; uint8_t sb[16]; + DEBUGF(fprintf(stderr, + "deflatehd: emit indname index=%zu, valuelen=%zu, " + "indexing=%d\n", + index, valuelen, inc_indexing)); + encvallen = nghttp2_hd_huff_encode_count(value, valuelen); blocklen = count_encoded_length(index + 1, 6); huffman = encvallen < valuelen; @@ -686,6 +702,11 @@ static int emit_newname_block(nghttp2_bufs *bufs, nghttp2_nv *nv, int name_huffman; int value_huffman; + DEBUGF(fprintf(stderr, + "deflatehd: emit newname namelen=%u, valuelen=%u, " + "indexing=%d\n", + nv->namelen, nv->valuelen, inc_indexing)); + encnamelen = nghttp2_hd_huff_encode_count(nv->name, nv->namelen); encvallen = nghttp2_hd_huff_encode_count(nv->value, nv->valuelen); name_huffman = encnamelen < nv->namelen; @@ -762,7 +783,7 @@ static nghttp2_hd_entry* add_hd_table_incremental(nghttp2_hd_context *context, } } } - DEBUGF(fprintf(stderr, "Remove item from header table:\n")); + DEBUGF(fprintf(stderr, "hpack: remove item from header table: ")); DEBUGF(fwrite(ent->nv.name, ent->nv.namelen, 1, stderr)); DEBUGF(fprintf(stderr, ": ")); DEBUGF(fwrite(ent->nv.value, ent->nv.valuelen, 1, stderr)); @@ -982,11 +1003,20 @@ static int deflate_nv(nghttp2_hd_deflater *deflater, nghttp2_hd_entry *ent; search_result res; + DEBUGF(fprintf(stderr, "deflatehd: deflating ")); + DEBUGF(fwrite(nv->name, nv->namelen, 1, stderr)); + DEBUGF(fprintf(stderr, ": ")); + DEBUGF(fwrite(nv->value, nv->valuelen, 1, stderr)); + DEBUGF(fprintf(stderr, "\n")); + res = search_hd_table(&deflater->ctx, nv); if(res.index != -1 && res.name_value_match) { size_t index = res.index; + DEBUGF(fprintf(stderr, "deflatehd: name/value match index=%zd\n", + res.index)); + ent = nghttp2_hd_table_get(&deflater->ctx, index); if(index >= deflater->ctx.hd_table.len) { nghttp2_hd_entry *new_ent; @@ -1054,6 +1084,9 @@ static int deflate_nv(nghttp2_hd_deflater *deflater, ssize_t index = -1; int incidx = 0; if(res.index != -1) { + DEBUGF(fprintf(stderr, "deflatehd: name match index=%zd\n", + res.index)); + index = res.index; } if(hd_deflate_should_indexing(deflater, nv)) { @@ -1152,6 +1185,10 @@ int nghttp2_hd_deflate_hd(nghttp2_hd_deflater *deflater, goto fail; } } + + DEBUGF(fprintf(stderr, + "deflatehd: all input name/value pairs were deflated\n")); + for(i = 0; i < deflater->ctx.hd_table.len; ++i) { nghttp2_hd_entry *ent = nghttp2_hd_ringbuf_get(&deflater->ctx.hd_table, i); @@ -1163,6 +1200,8 @@ int nghttp2_hd_deflate_hd(nghttp2_hd_deflater *deflater, return 0; fail: + DEBUGF(fprintf(stderr, "deflatehd: error return %d\n", rv)); + deflater->ctx.bad = 1; return rv; } @@ -1195,11 +1234,13 @@ static ssize_t hd_inflate_read_len(nghttp2_hd_inflater *inflater, *rfin = 0; nin = decode_length(&inflater->left, rfin, inflater->left, in, last, prefix); if(inflater->left == -1) { - DEBUGF(fprintf(stderr, "invalid integer\n")); + DEBUGF(fprintf(stderr, "inflatehd: invalid integer\n")); return NGHTTP2_ERR_HEADER_COMP; } if((size_t)inflater->left > maxlen) { - DEBUGF(fprintf(stderr, "integer exceeds the maximum value %zu\n", maxlen)); + DEBUGF(fprintf(stderr, + "inflatehd: integer exceeded the maximum value %zu\n", + maxlen)); return NGHTTP2_ERR_HEADER_COMP; } return nin - in; @@ -1234,7 +1275,7 @@ static ssize_t hd_inflate_read_huff(nghttp2_hd_inflater *inflater, return NGHTTP2_ERR_HEADER_COMP; } if(rv < 0) { - DEBUGF(fprintf(stderr, "huffman decoding failed\n")); + DEBUGF(fprintf(stderr, "inflatehd: huffman decoding failed\n")); return rv; } inflater->left -= rv; @@ -1302,7 +1343,7 @@ static int hd_inflate_commit_indexed(nghttp2_hd_inflater *inflater, emit_indexed_header(nv_out, ent); return 0; } - DEBUGF(fprintf(stderr, "Toggle off item:\n")); + DEBUGF(fprintf(stderr, "inflatehd: toggle off item: ")); DEBUGF(fwrite(ent->nv.name, ent->nv.namelen, 1, stderr)); DEBUGF(fprintf(stderr, ": ")); DEBUGF(fwrite(ent->nv.value, ent->nv.valuelen, 1, stderr)); @@ -1474,7 +1515,7 @@ ssize_t nghttp2_hd_inflate_hd(nghttp2_hd_inflater *inflater, return NGHTTP2_ERR_HEADER_COMP; } - DEBUGF(fprintf(stderr, "nghtp2_hd_infalte_hd start state=%d\n", + DEBUGF(fprintf(stderr, "inflatehd: start state=%d\n", inflater->state)); hd_inflate_keep_free(inflater); *inflate_flags = NGHTTP2_HD_INFLATE_NONE; @@ -1482,26 +1523,28 @@ ssize_t nghttp2_hd_inflate_hd(nghttp2_hd_inflater *inflater, switch(inflater->state) { case NGHTTP2_HD_STATE_OPCODE: if(*in == 0x80u) { - DEBUGF(fprintf(stderr, "Encoding context update\n")); + DEBUGF(fprintf(stderr, "inflatehd: encoding context update\n")); inflater->opcode = NGHTTP2_HD_OPCODE_INDEXED; inflater->state = NGHTTP2_HD_STATE_CONTEXT_UPDATE; ++in; } else if(*in & 0x80u) { - DEBUGF(fprintf(stderr, "Indexed repr\n")); + DEBUGF(fprintf(stderr, "inflatehd: indexed repr\n")); inflater->opcode = NGHTTP2_HD_OPCODE_INDEXED; inflater->state = NGHTTP2_HD_STATE_READ_INDEX; } else { if(*in == 0x40 || *in == 0) { - DEBUGF(fprintf(stderr, "Literal header repr - new name\n")); + DEBUGF(fprintf(stderr, + "inflatehd: literal header repr - new name\n")); inflater->opcode = NGHTTP2_HD_OPCODE_NEWNAME; inflater->state = NGHTTP2_HD_STATE_NEWNAME_CHECK_NAMELEN; } else { - DEBUGF(fprintf(stderr, "Literal header repr - indexed name\n")); + DEBUGF(fprintf(stderr, + "inflatehd: literal header repr - indexed name\n")); inflater->opcode = NGHTTP2_HD_OPCODE_INDNAME; inflater->state = NGHTTP2_HD_STATE_READ_INDEX; } inflater->index_required = (*in & 0x40) == 0; - DEBUGF(fprintf(stderr, "indexing required=%d\n", + DEBUGF(fprintf(stderr, "inflatehd: indexing required=%d\n", inflater->index_required != 0)); if(inflater->opcode == NGHTTP2_HD_OPCODE_NEWNAME) { ++in; @@ -1516,13 +1559,13 @@ ssize_t nghttp2_hd_inflate_hd(nghttp2_hd_inflater *inflater, goto fail; } ++in; - DEBUGF(fprintf(stderr, "Clearing reference set\n")); + DEBUGF(fprintf(stderr, "inflatehd: clearing reference set\n")); clear_refset(&inflater->ctx); inflater->state = NGHTTP2_HD_STATE_OPCODE; break; } /* Header table size change */ - DEBUGF(fprintf(stderr, "Header table size change\n")); + DEBUGF(fprintf(stderr, "inflatehd: header table size change\n")); inflater->state = NGHTTP2_HD_STATE_READ_TABLE_SIZE; break; case NGHTTP2_HD_STATE_READ_TABLE_SIZE: @@ -1536,7 +1579,7 @@ ssize_t nghttp2_hd_inflate_hd(nghttp2_hd_inflater *inflater, if(!rfin) { goto almost_ok; } - DEBUGF(fprintf(stderr, "table_size=%zd\n", inflater->left)); + DEBUGF(fprintf(stderr, "inflatehd: table_size=%zd\n", inflater->left)); inflater->ctx.hd_table_bufsize_max = inflater->left; hd_context_shrink_table_size(&inflater->ctx); inflater->state = NGHTTP2_HD_STATE_OPCODE; @@ -1554,7 +1597,7 @@ ssize_t nghttp2_hd_inflate_hd(nghttp2_hd_inflater *inflater, if(!rfin) { goto almost_ok; } - DEBUGF(fprintf(stderr, "index=%zd\n", inflater->left)); + DEBUGF(fprintf(stderr, "inflatehd: index=%zd\n", inflater->left)); if(inflater->opcode == NGHTTP2_HD_OPCODE_INDEXED) { inflater->index = inflater->left; assert(inflater->index > 0); @@ -1582,7 +1625,7 @@ ssize_t nghttp2_hd_inflate_hd(nghttp2_hd_inflater *inflater, hd_inflate_set_huffman_encoded(inflater, in); inflater->state = NGHTTP2_HD_STATE_NEWNAME_READ_NAMELEN; inflater->left = 0; - DEBUGF(fprintf(stderr, "huffman encoded=%d\n", + DEBUGF(fprintf(stderr, "inflatehd: huffman encoded=%d\n", inflater->huffman_encoded != 0)); /* Fall through */ case NGHTTP2_HD_STATE_NEWNAME_READ_NAMELEN: @@ -1594,7 +1637,8 @@ ssize_t nghttp2_hd_inflate_hd(nghttp2_hd_inflater *inflater, } in += rv; if(!rfin) { - DEBUGF(fprintf(stderr, "integer not fully decoded. current=%zd\n", + DEBUGF(fprintf(stderr, + "inflatehd: integer not fully decoded. current=%zd\n", inflater->left)); goto almost_ok; @@ -1618,10 +1662,11 @@ ssize_t nghttp2_hd_inflate_hd(nghttp2_hd_inflater *inflater, in += rv; - DEBUGF(fprintf(stderr, "%zd bytes read\n", rv)); + DEBUGF(fprintf(stderr, "inflatehd: %zd bytes read\n", rv)); if(inflater->left) { - DEBUGF(fprintf(stderr, "still %zd bytes to go\n", inflater->left)); + DEBUGF(fprintf(stderr, + "inflatehd: still %zd bytes to go\n", inflater->left)); goto almost_ok; } @@ -1637,9 +1682,10 @@ ssize_t nghttp2_hd_inflate_hd(nghttp2_hd_inflater *inflater, in += rv; - DEBUGF(fprintf(stderr, "%zd bytes read\n", rv)); + DEBUGF(fprintf(stderr, "inflatehd: %zd bytes read\n", rv)); if(inflater->left) { - DEBUGF(fprintf(stderr, "still %zd bytes to go\n", inflater->left)); + DEBUGF(fprintf(stderr, + "inflatehd: still %zd bytes to go\n", inflater->left)); goto almost_ok; } @@ -1651,7 +1697,7 @@ ssize_t nghttp2_hd_inflate_hd(nghttp2_hd_inflater *inflater, hd_inflate_set_huffman_encoded(inflater, in); inflater->state = NGHTTP2_HD_STATE_READ_VALUELEN; inflater->left = 0; - DEBUGF(fprintf(stderr, "huffman encoded=%d\n", + DEBUGF(fprintf(stderr, "inflatehd: huffman encoded=%d\n", inflater->huffman_encoded != 0)); /* Fall through */ case NGHTTP2_HD_STATE_READ_VALUELEN: @@ -1668,7 +1714,7 @@ ssize_t nghttp2_hd_inflate_hd(nghttp2_hd_inflater *inflater, goto almost_ok; } - DEBUGF(fprintf(stderr, "valuelen=%zd\n", inflater->left)); + DEBUGF(fprintf(stderr, "inflatehd: valuelen=%zd\n", inflater->left)); if(inflater->left == 0) { if(inflater->opcode == NGHTTP2_HD_OPCODE_NEWNAME) { rv = hd_inflate_commit_newname(inflater, nv_out); @@ -1699,10 +1745,11 @@ ssize_t nghttp2_hd_inflate_hd(nghttp2_hd_inflater *inflater, in += rv; - DEBUGF(fprintf(stderr, "%zd bytes read\n", rv)); + DEBUGF(fprintf(stderr, "inflatehd: %zd bytes read\n", rv)); if(inflater->left) { - DEBUGF(fprintf(stderr, "still %zd bytes to go\n", inflater->left)); + DEBUGF(fprintf(stderr, + "inflatehd: still %zd bytes to go\n", inflater->left)); goto almost_ok; } @@ -1724,17 +1771,18 @@ ssize_t nghttp2_hd_inflate_hd(nghttp2_hd_inflater *inflater, case NGHTTP2_HD_STATE_READ_VALUE: rv = hd_inflate_read(inflater, &inflater->valuebufs, in, last); if(rv < 0) { - DEBUGF(fprintf(stderr, "value read failure %zd: %s\n", + DEBUGF(fprintf(stderr, "inflatehd: value read failure %zd: %s\n", rv, nghttp2_strerror(rv))); goto fail; } in += rv; - DEBUGF(fprintf(stderr, "%zd bytes read\n", rv)); + DEBUGF(fprintf(stderr, "inflatehd: %zd bytes read\n", rv)); if(inflater->left) { - DEBUGF(fprintf(stderr, "still %zd bytes to go\n", inflater->left)); + DEBUGF(fprintf(stderr, + "inflatehd: still %zd bytes to go\n", inflater->left)); goto almost_ok; } @@ -1754,10 +1802,19 @@ ssize_t nghttp2_hd_inflate_hd(nghttp2_hd_inflater *inflater, return in - first; } } + assert(in == last); + + DEBUGF(fprintf(stderr, "inflatehd: all input bytes were processed\n")); + if(in_final) { + DEBUGF(fprintf(stderr, "inflatehd: in_final set\n")); + if(inflater->state != NGHTTP2_HD_STATE_OPCODE) { + DEBUGF(fprintf(stderr, "inflatehd: unacceptable state=%d\n", + inflater->state)); rv = NGHTTP2_ERR_HEADER_COMP; + goto fail; } for(; inflater->end_headers_index < inflater->ctx.hd_table.len; @@ -1780,12 +1837,17 @@ ssize_t nghttp2_hd_inflate_hd(nghttp2_hd_inflater *inflater, almost_ok: if(in_final && inflater->state != NGHTTP2_HD_STATE_OPCODE) { + DEBUGF(fprintf(stderr, "inflatehd: input ended prematurely\n")); + rv = NGHTTP2_ERR_HEADER_COMP; + goto fail; } return in - first; fail: + DEBUGF(fprintf(stderr, "inflatehd: error return %zd\n", rv)); + inflater->ctx.bad = 1; return rv; } diff --git a/lib/nghttp2_session.c b/lib/nghttp2_session.c index 96a4b55a..02430362 100644 --- a/lib/nghttp2_session.c +++ b/lib/nghttp2_session.c @@ -206,8 +206,8 @@ static void init_settings(uint32_t *settings) static void nghttp2_active_outbound_item_reset (nghttp2_active_outbound_item *aob) { - DEBUGF(fprintf(stderr, "reset nghttp2_active_outbound_item\n")); - DEBUGF(fprintf(stderr, "aob->item = %p\n", aob->item)); + DEBUGF(fprintf(stderr, "send: reset nghttp2_active_outbound_item\n")); + DEBUGF(fprintf(stderr, "send: aob->item = %p\n", aob->item)); nghttp2_outbound_item_free(aob->item); free(aob->item); aob->item = NULL; @@ -1037,12 +1037,19 @@ static size_t nghttp2_session_next_data_read(nghttp2_session *session, { int32_t window_size = NGHTTP2_DATA_PAYLOAD_LENGTH; - DEBUGF(fprintf(stderr, "connection remote_window_size=%d\n", - session->remote_window_size)); + DEBUGF(fprintf(stderr, + "send: remote windowsize connection=%d, " + "stream(id %d)=%d\n", + session->remote_window_size, + stream->stream_id, + stream->remote_window_size)); /* Take into account both connection-level flow control here */ window_size = nghttp2_min(window_size, session->remote_window_size); window_size = nghttp2_min(window_size, stream->remote_window_size); + + DEBUGF(fprintf(stderr, "send: available window=%d\n", window_size)); + if(window_size > 0) { return window_size; } @@ -1146,7 +1153,8 @@ static int session_headers_add_pad(nghttp2_session *session, padlen = padded_payloadlen - frame->hd.length; - DEBUGF(fprintf(stderr, "padding selected: payloadlen=%zu, padlen=%zu\n", + DEBUGF(fprintf(stderr, + "send: padding selected: payloadlen=%zu, padlen=%zu\n", padded_payloadlen, padlen)); rv = nghttp2_frame_add_pad(framebufs, &frame->hd, padlen, @@ -1211,7 +1219,7 @@ static int nghttp2_session_prep_frame(nghttp2_session *session, } DEBUGF(fprintf(stderr, - "before padding, HEADERS serialized in %zd bytes\n", + "send: before padding, HEADERS serialized in %zd bytes\n", nghttp2_bufs_len(&session->aob.framebufs))); framebuflen = session_headers_add_pad(session, frame); @@ -1241,7 +1249,7 @@ static int nghttp2_session_prep_frame(nghttp2_session *session, break; } - DEBUGF(fprintf(stderr, "HEADERS serialized in %zd bytes\n", + DEBUGF(fprintf(stderr, "send: HEADERS finally serialized in %zd bytes\n", nghttp2_bufs_len(&session->aob.framebufs))); break; @@ -1538,7 +1546,7 @@ static int nghttp2_session_after_frame_sent(nghttp2_session *session) if(nghttp2_bufs_next_present(framebufs)) { framebufs->cur = framebufs->cur->next; - DEBUGF(fprintf(stderr, "send CONTINUATION frame, %zu bytes\n", + DEBUGF(fprintf(stderr, "send: next CONTINUATION frame, %zu bytes\n", nghttp2_buf_len(&framebufs->cur->buf))); return 0; @@ -1805,12 +1813,12 @@ ssize_t nghttp2_session_mem_send(nghttp2_session *session, } rv = nghttp2_session_prep_frame(session, item); if(rv == NGHTTP2_ERR_DEFERRED) { - DEBUGF(fprintf(stderr, "frame deferred\n")); + DEBUGF(fprintf(stderr, "send: frame transmission deferred\n")); rv = 0; break; } if(rv < 0) { - DEBUGF(fprintf(stderr, "frame preparation failed with %s\n", + DEBUGF(fprintf(stderr, "send: frame preparation failed with %s\n", nghttp2_strerror(rv))); /* TODO If the error comes from compressor, the connection must be closed. */ @@ -1853,13 +1861,22 @@ ssize_t nghttp2_session_mem_send(nghttp2_session *session, frame = nghttp2_outbound_item_get_ctrl_frame(item); + DEBUGF(fprintf(stderr, + "send: next frame: payloadlen=%zu, type=%u, " + "flags=0x%02x, stream_id=%d\n", + frame->hd.length, frame->hd.type, frame->hd.flags, + frame->hd.stream_id)); + rv = session_call_before_frame_send(session, frame); if(nghttp2_is_fatal(rv)) { return rv; } + } else { + DEBUGF(fprintf(stderr, "send: next frame: DATA\n")); } - DEBUGF(fprintf(stderr, "start transmitting type %d frame %zd bytes\n", + DEBUGF(fprintf(stderr, + "send: start transmitting frame type=%u, length=%zd\n", framebufs->cur->buf.pos[2], framebufs->cur->buf.last - framebufs->cur->buf.pos)); @@ -1874,7 +1891,7 @@ ssize_t nghttp2_session_mem_send(nghttp2_session *session, buf = &framebufs->cur->buf; if(buf->pos == buf->last) { - DEBUGF(fprintf(stderr, "end transmission of frame\n")); + DEBUGF(fprintf(stderr, "send: end transmission of a frame\n")); /* Frame has completely sent */ rv = nghttp2_session_after_frame_sent(session); @@ -1965,7 +1982,7 @@ static int session_call_on_begin_headers(nghttp2_session *session, nghttp2_frame *frame) { int rv; - DEBUGF(fprintf(stderr, "Call on_begin_headers callback stream_id=%d\n", + DEBUGF(fprintf(stderr, "recv: call on_begin_headers callback stream_id=%d\n", frame->hd.stream_id)); if(session->callbacks.on_begin_headers_callback) { rv = session->callbacks.on_begin_headers_callback(session, frame, @@ -2150,7 +2167,7 @@ static ssize_t inflate_header_block(nghttp2_session *session, *readlen_ptr = 0; - DEBUGF(fprintf(stderr, "processing header block %zu bytes\n", inlen)); + DEBUGF(fprintf(stderr, "recv: decoding header block %zu bytes\n", inlen)); for(;;) { inflate_flags = 0; rv = nghttp2_hd_inflate_hd(&session->hd_inflater, &nv, &inflate_flags, @@ -3492,7 +3509,7 @@ static int inbound_frame_handle_pad(nghttp2_inbound_frame *iframe, inbound_frame_reset_left(iframe, 1); return 1; } - DEBUGF(fprintf(stderr, "no padding\n")); + DEBUGF(fprintf(stderr, "recv: no padding in payload\n")); return 0; } @@ -3510,7 +3527,7 @@ static ssize_t inbound_frame_compute_pad(nghttp2_inbound_frame *iframe) ++padlen; } ++padlen; - DEBUGF(fprintf(stderr, "padlen=%zu\n", padlen)); + DEBUGF(fprintf(stderr, "recv: padlen=%zu\n", padlen)); /* We cannot use iframe->frame.hd.length because of CONTINUATION */ if(padlen - (padlen > 255) - 1 > iframe->payloadleft) { return -1; @@ -3555,13 +3572,14 @@ ssize_t nghttp2_session_mem_recv(nghttp2_session *session, nghttp2_frame_hd cont_hd; nghttp2_stream *stream; - DEBUGF(fprintf(stderr, "connection recv_window_size=%d, local_window=%d\n", + DEBUGF(fprintf(stderr, + "recv: connection recv_window_size=%d, local_window=%d\n", session->recv_window_size, session->local_window_size)); for(;;) { switch(iframe->state) { case NGHTTP2_IB_READ_HEAD: - DEBUGF(fprintf(stderr, "[IB_READ_HEAD]\n")); + DEBUGF(fprintf(stderr, "recv: [IB_READ_HEAD]\n")); readlen = inbound_frame_buf_read(iframe, in, last); in += readlen; if(iframe->left) { @@ -3571,11 +3589,17 @@ ssize_t nghttp2_session_mem_recv(nghttp2_session *session, nghttp2_frame_unpack_frame_hd(&iframe->frame.hd, iframe->buf); iframe->payloadleft = iframe->frame.hd.length; - DEBUGF(fprintf(stderr, "payloadlen=%zu\n", iframe->payloadleft)); + DEBUGF(fprintf(stderr, + "recv: payloadlen=%zu, type=%u, flags=0x%02x, " + "stream_id=%d\n", + iframe->frame.hd.length, + iframe->frame.hd.type, + iframe->frame.hd.flags, + iframe->frame.hd.stream_id)); switch(iframe->frame.hd.type) { case NGHTTP2_DATA: { - DEBUGF(fprintf(stderr, "DATA\n")); + DEBUGF(fprintf(stderr, "recv: DATA\n")); iframe->frame.hd.flags &= (NGHTTP2_FLAG_END_STREAM | NGHTTP2_FLAG_END_SEGMENT | NGHTTP2_FLAG_PAD_LOW | @@ -3585,7 +3609,7 @@ ssize_t nghttp2_session_mem_recv(nghttp2_session *session, busy = 1; rv = nghttp2_session_on_data_received_fail_fast(session); if(rv == NGHTTP2_ERR_IGN_PAYLOAD) { - DEBUGF(fprintf(stderr, "DATA not allowed stream_id=%d\n", + DEBUGF(fprintf(stderr, "recv: DATA not allowed stream_id=%d\n", iframe->frame.hd.stream_id)); iframe->state = NGHTTP2_IB_IGN_DATA; break; @@ -3617,7 +3641,7 @@ ssize_t nghttp2_session_mem_recv(nghttp2_session *session, NGHTTP2_FLAG_PRIORITY | NGHTTP2_FLAG_PAD_LOW | NGHTTP2_FLAG_PAD_HIGH); - DEBUGF(fprintf(stderr, "HEADERS\n")); + DEBUGF(fprintf(stderr, "recv: HEADERS\n")); rv = inbound_frame_handle_pad(iframe, &iframe->frame.hd); if(rv < 0) { busy = 1; @@ -3660,13 +3684,13 @@ ssize_t nghttp2_session_mem_recv(nghttp2_session *session, #ifdef DEBUGBUILD switch(iframe->frame.hd.type) { case NGHTTP2_PRIORITY: - DEBUGF(fprintf(stderr, "PRIORITY\n")); + DEBUGF(fprintf(stderr, "recv: PRIORITY\n")); break; case NGHTTP2_RST_STREAM: - DEBUGF(fprintf(stderr, "RST_STREAM\n")); + DEBUGF(fprintf(stderr, "recv: RST_STREAM\n")); break; case NGHTTP2_WINDOW_UPDATE: - DEBUGF(fprintf(stderr, "WINDOW_UPDATE\n")); + DEBUGF(fprintf(stderr, "recv: WINDOW_UPDATE\n")); break; } #endif /* DEBUGBUILD */ @@ -3680,7 +3704,7 @@ ssize_t nghttp2_session_mem_recv(nghttp2_session *session, inbound_frame_reset_left(iframe, 4); break; case NGHTTP2_SETTINGS: - DEBUGF(fprintf(stderr, "SETTINGS\n")); + DEBUGF(fprintf(stderr, "recv: SETTINGS\n")); iframe->frame.hd.flags &= NGHTTP2_FLAG_ACK; if((iframe->frame.hd.length % NGHTTP2_FRAME_SETTINGS_ENTRY_LENGTH) || ((iframe->frame.hd.flags & NGHTTP2_FLAG_ACK) && @@ -3699,7 +3723,7 @@ ssize_t nghttp2_session_mem_recv(nghttp2_session *session, inbound_frame_reset_left(iframe, 0); break; case NGHTTP2_PUSH_PROMISE: - DEBUGF(fprintf(stderr, "PUSH_PROMISE\n")); + DEBUGF(fprintf(stderr, "recv: PUSH_PROMISE\n")); iframe->frame.hd.flags &= (NGHTTP2_FLAG_END_HEADERS | NGHTTP2_FLAG_PAD_LOW | NGHTTP2_FLAG_PAD_HIGH); @@ -3727,7 +3751,7 @@ ssize_t nghttp2_session_mem_recv(nghttp2_session *session, inbound_frame_reset_left(iframe, 4); break; case NGHTTP2_PING: - DEBUGF(fprintf(stderr, "PING\n")); + DEBUGF(fprintf(stderr, "recv: PING\n")); iframe->frame.hd.flags &= NGHTTP2_FLAG_ACK; if(iframe->payloadleft != 8) { busy = 1; @@ -3738,7 +3762,7 @@ ssize_t nghttp2_session_mem_recv(nghttp2_session *session, inbound_frame_reset_left(iframe, 8); break; case NGHTTP2_GOAWAY: - DEBUGF(fprintf(stderr, "GOAWAY\n")); + DEBUGF(fprintf(stderr, "recv: GOAWAY\n")); iframe->frame.hd.flags = NGHTTP2_FLAG_NONE; if(iframe->payloadleft < 8) { busy = 1; @@ -3749,7 +3773,7 @@ ssize_t nghttp2_session_mem_recv(nghttp2_session *session, inbound_frame_reset_left(iframe, 8); break; default: - DEBUGF(fprintf(stderr, "unknown frame\n")); + DEBUGF(fprintf(stderr, "recv: unknown frame\n")); /* Receiving unknown frame type and CONTINUATION in this state are subject to connection error of type PROTOCOL_ERROR */ rv = nghttp2_session_terminate_session(session, @@ -3763,11 +3787,11 @@ ssize_t nghttp2_session_mem_recv(nghttp2_session *session, } break; case NGHTTP2_IB_READ_NBYTE: - DEBUGF(fprintf(stderr, "[IB_READ_NBYTE]\n")); + DEBUGF(fprintf(stderr, "recv: [IB_READ_NBYTE]\n")); readlen = inbound_frame_buf_read(iframe, in, last); in += readlen; iframe->payloadleft -= readlen; - DEBUGF(fprintf(stderr, "readlen=%zu, payloadleft=%zu, left=%zu\n", + DEBUGF(fprintf(stderr, "recv: readlen=%zu, payloadleft=%zu, left=%zu\n", readlen, iframe->payloadleft, iframe->left)); if(iframe->left) { return in - first; @@ -3888,13 +3912,13 @@ ssize_t nghttp2_session_mem_recv(nghttp2_session *session, ssize_t data_readlen; #ifdef DEBUGBUILD if(iframe->state == NGHTTP2_IB_READ_HEADER_BLOCK) { - fprintf(stderr, "[IB_READ_HEADER_BLOCK]\n"); + fprintf(stderr, "recv: [IB_READ_HEADER_BLOCK]\n"); } else { - fprintf(stderr, "[IB_IGN_HEADER_BLOCK]\n"); + fprintf(stderr, "recv: [IB_IGN_HEADER_BLOCK]\n"); } #endif /* DEBUGBUILD */ readlen = inbound_frame_payload_readlen(iframe, in, last); - DEBUGF(fprintf(stderr, "readlen=%zu, payloadleft=%zu\n", + DEBUGF(fprintf(stderr, "recv: readlen=%zu, payloadleft=%zu\n", readlen, iframe->payloadleft - readlen)); data_readlen = inbound_frame_effective_readlen @@ -3904,7 +3928,7 @@ ssize_t nghttp2_session_mem_recv(nghttp2_session *session, size_t hd_proclen = 0; trail_padlen = nghttp2_frame_trail_padlen(&iframe->frame, iframe->padlen); - DEBUGF(fprintf(stderr, "block final=%d\n", + DEBUGF(fprintf(stderr, "recv: block final=%d\n", (iframe->frame.hd.flags & NGHTTP2_FLAG_END_HEADERS) && iframe->payloadleft - data_readlen == trail_padlen)); @@ -3989,11 +4013,11 @@ ssize_t nghttp2_session_mem_recv(nghttp2_session *session, break; } case NGHTTP2_IB_IGN_PAYLOAD: - DEBUGF(fprintf(stderr, "[IB_IGN_PAYLOAD]\n")); + DEBUGF(fprintf(stderr, "recv: [IB_IGN_PAYLOAD]\n")); readlen = inbound_frame_payload_readlen(iframe, in, last); iframe->payloadleft -= readlen; in += readlen; - DEBUGF(fprintf(stderr, "readlen=%zu, payloadleft=%zu\n", + DEBUGF(fprintf(stderr, "recv: readlen=%zu, payloadleft=%zu\n", readlen, iframe->payloadleft)); if(iframe->payloadleft) { break; @@ -4001,7 +4025,7 @@ ssize_t nghttp2_session_mem_recv(nghttp2_session *session, nghttp2_inbound_frame_reset(session); break; case NGHTTP2_IB_FRAME_SIZE_ERROR: - DEBUGF(fprintf(stderr, "[IB_FRAME_SIZE_ERROR]\n")); + DEBUGF(fprintf(stderr, "recv: [IB_FRAME_SIZE_ERROR]\n")); rv = session_handle_frame_size_error(session, &iframe->frame); if(nghttp2_is_fatal(rv)) { return rv; @@ -4010,11 +4034,11 @@ ssize_t nghttp2_session_mem_recv(nghttp2_session *session, iframe->state = NGHTTP2_IB_IGN_PAYLOAD; break; case NGHTTP2_IB_READ_SETTINGS: - DEBUGF(fprintf(stderr, "[IB_READ_SETTINGS]\n")); + DEBUGF(fprintf(stderr, "recv: [IB_READ_SETTINGS]\n")); readlen = inbound_frame_buf_read(iframe, in, last); iframe->payloadleft -= readlen; in += readlen; - DEBUGF(fprintf(stderr, "readlen=%zu, payloadleft=%zu\n", + DEBUGF(fprintf(stderr, "recv: readlen=%zu, payloadleft=%zu\n", readlen, iframe->payloadleft)); if(iframe->left) { break; @@ -4022,7 +4046,7 @@ ssize_t nghttp2_session_mem_recv(nghttp2_session *session, if(readlen > 0) { rv = inbound_frame_set_settings_entry(iframe); if(rv != 0) { - DEBUGF(fprintf(stderr, "bad settings\n")); + DEBUGF(fprintf(stderr, "recv: bad settings received\n")); rv = nghttp2_session_terminate_session(session, NGHTTP2_PROTOCOL_ERROR); if(nghttp2_is_fatal(rv)) { @@ -4047,11 +4071,11 @@ ssize_t nghttp2_session_mem_recv(nghttp2_session *session, nghttp2_inbound_frame_reset(session); break; case NGHTTP2_IB_READ_GOAWAY_DEBUG: - DEBUGF(fprintf(stderr, "[IB_READ_GOAWAY_DEBUG]\n")); + DEBUGF(fprintf(stderr, "recv: [IB_READ_GOAWAY_DEBUG]\n")); readlen = inbound_frame_payload_readlen(iframe, in, last); iframe->payloadleft -= readlen; in += readlen; - DEBUGF(fprintf(stderr, "readlen=%zu, payloadleft=%zu\n", + DEBUGF(fprintf(stderr, "recv: readlen=%zu, payloadleft=%zu\n", readlen, iframe->payloadleft)); if(iframe->payloadleft) { break; @@ -4066,9 +4090,9 @@ ssize_t nghttp2_session_mem_recv(nghttp2_session *session, case NGHTTP2_IB_IGN_CONTINUATION: #ifdef DEBUGBUILD if(iframe->state == NGHTTP2_IB_EXPECT_CONTINUATION) { - fprintf(stderr, "[IB_EXPECT_CONTINUATION]\n"); + fprintf(stderr, "recv: [IB_EXPECT_CONTINUATION]\n"); } else { - fprintf(stderr, "[IB_IGN_CONTINUATION]\n"); + fprintf(stderr, "recv: [IB_IGN_CONTINUATION]\n"); } #endif /* DEBUGBUILD */ readlen = inbound_frame_buf_read(iframe, in, last); @@ -4079,11 +4103,16 @@ ssize_t nghttp2_session_mem_recv(nghttp2_session *session, nghttp2_frame_unpack_frame_hd(&cont_hd, iframe->buf); iframe->payloadleft = cont_hd.length; - DEBUGF(fprintf(stderr, "payloadlen=%zu\n", iframe->payloadleft)); + DEBUGF(fprintf(stderr, + "recv: payloadlen=%zu, type=%u, flags=0x%02x, " + "stream_id=%d\n", + cont_hd.length, cont_hd.type, cont_hd.flags, + cont_hd.stream_id)); if(cont_hd.type != NGHTTP2_CONTINUATION || cont_hd.stream_id != iframe->frame.hd.stream_id) { - DEBUGF(fprintf(stderr, "expected stream_id=%d, type=%d, but " + DEBUGF(fprintf(stderr, + "recv: expected stream_id=%d, type=%d, but " "got stream_id=%d, type=%d\n", iframe->frame.hd.stream_id, NGHTTP2_CONTINUATION, cont_hd.stream_id, cont_hd.type)); @@ -4134,15 +4163,15 @@ ssize_t nghttp2_session_mem_recv(nghttp2_session *session, case NGHTTP2_IB_IGN_PAD_CONTINUATION: #ifdef DEBUGBUILD if(iframe->state == NGHTTP2_IB_READ_PAD_CONTINUATION) { - fprintf(stderr, "[IB_READ_PAD_CONTINUATION]\n"); + fprintf(stderr, "recv: [IB_READ_PAD_CONTINUATION]\n"); } else { - fprintf(stderr, "[IB_IGN_PAD_CONTINUATION]\n"); + fprintf(stderr, "recv: [IB_IGN_PAD_CONTINUATION]\n"); } #endif /* DEBUGBUILD */ readlen = inbound_frame_buf_read(iframe, in, last); in += readlen; iframe->payloadleft -= readlen; - DEBUGF(fprintf(stderr, "readlen=%zu, payloadleft=%zu, left=%zu\n", + DEBUGF(fprintf(stderr, "recv: readlen=%zu, payloadleft=%zu, left=%zu\n", readlen, iframe->payloadleft, iframe->left)); if(iframe->left) { return in - first; @@ -4171,11 +4200,11 @@ ssize_t nghttp2_session_mem_recv(nghttp2_session *session, } break; case NGHTTP2_IB_READ_PAD_DATA: - DEBUGF(fprintf(stderr, "[IB_READ_PAD_DATA]\n")); + DEBUGF(fprintf(stderr, "recv: [IB_READ_PAD_DATA]\n")); readlen = inbound_frame_buf_read(iframe, in, last); in += readlen; iframe->payloadleft -= readlen; - DEBUGF(fprintf(stderr, "readlen=%zu, payloadleft=%zu, left=%zu\n", + DEBUGF(fprintf(stderr, "recv: readlen=%zu, payloadleft=%zu, left=%zu\n", readlen, iframe->payloadleft, iframe->left)); /* PAD_HIGH and PAD_LOW are subject to flow control */ @@ -4215,11 +4244,11 @@ ssize_t nghttp2_session_mem_recv(nghttp2_session *session, iframe->state = NGHTTP2_IB_READ_DATA; break; case NGHTTP2_IB_READ_DATA: - DEBUGF(fprintf(stderr, "[IB_READ_DATA]\n")); + DEBUGF(fprintf(stderr, "recv: [IB_READ_DATA]\n")); readlen = inbound_frame_payload_readlen(iframe, in, last); iframe->payloadleft -= readlen; in += readlen; - DEBUGF(fprintf(stderr, "readlen=%zu, payloadleft=%zu\n", + DEBUGF(fprintf(stderr, "recv: readlen=%zu, payloadleft=%zu\n", readlen, iframe->payloadleft)); if(readlen > 0) { ssize_t data_readlen; @@ -4241,8 +4270,9 @@ ssize_t nghttp2_session_mem_recv(nghttp2_session *session, } data_readlen = inbound_frame_effective_readlen (iframe, iframe->payloadleft, readlen); - DEBUGF(fprintf(stderr, "data_readlen=%zu\n", data_readlen)); - if(data_readlen > 0 && session->callbacks.on_data_chunk_recv_callback) { + DEBUGF(fprintf(stderr, "recv: data_readlen=%zu\n", data_readlen)); + if(data_readlen > 0 && + session->callbacks.on_data_chunk_recv_callback) { rv = session->callbacks.on_data_chunk_recv_callback (session, iframe->frame.hd.flags, @@ -4274,11 +4304,11 @@ ssize_t nghttp2_session_mem_recv(nghttp2_session *session, nghttp2_inbound_frame_reset(session); break; case NGHTTP2_IB_IGN_DATA: - DEBUGF(fprintf(stderr, "[IB_IGN_DATA]\n")); + DEBUGF(fprintf(stderr, "recv: [IB_IGN_DATA]\n")); readlen = inbound_frame_payload_readlen(iframe, in, last); iframe->payloadleft -= readlen; in += readlen; - DEBUGF(fprintf(stderr, "readlen=%zu, payloadleft=%zu\n", + DEBUGF(fprintf(stderr, "recv: readlen=%zu, payloadleft=%zu\n", readlen, iframe->payloadleft)); if(readlen > 0) { /* Update connection-level flow control window for ignored @@ -4494,7 +4524,7 @@ ssize_t nghttp2_session_pack_data(nghttp2_session *session, if(payloadlen == NGHTTP2_ERR_DEFERRED || payloadlen == NGHTTP2_ERR_TEMPORAL_CALLBACK_FAILURE) { - DEBUGF(fprintf(stderr, "DATA postponed due to %s\n", + DEBUGF(fprintf(stderr, "send: DATA postponed due to %s\n", nghttp2_strerror(payloadlen))); return payloadlen;