From: Stefan Eissing Date: Fri, 4 Aug 2023 09:35:03 +0000 (+0200) Subject: http2: cleanup trace messages X-Git-Tag: curl-8_3_0~217 X-Git-Url: http://git.ipfire.org/?a=commitdiff_plain;h=fbacb14c4c0fbb31bde308c8878c6b694b6043c6;p=thirdparty%2Fcurl.git http2: cleanup trace messages - more compact format with bracketed stream id - all frames traced in and out Closes #11592 --- diff --git a/lib/http2.c b/lib/http2.c index 25e965e6f9..d1921a4a69 100644 --- a/lib/http2.c +++ b/lib/http2.c @@ -217,7 +217,7 @@ static void drain_stream(struct Curl_cfilter *cf, (stream->upload_left || stream->upload_blocked_len)) bits |= CURL_CSELECT_OUT; if(data->state.dselect_bits != bits) { - CURL_TRC_CF(data, cf, "[h2sid=%d] DRAIN dselect_bits=%x", + CURL_TRC_CF(data, cf, "[%d] DRAIN dselect_bits=%x", stream->id, bits); data->state.dselect_bits = bits; Curl_expire(data, 0, EXPIRE_RUN_NOW); @@ -281,7 +281,7 @@ static void http2_data_done(struct Curl_cfilter *cf, if(ctx->h2) { if(!stream->closed && stream->id > 0) { /* RST_STREAM */ - CURL_TRC_CF(data, cf, "[h2sid=%d] premature DATA_DONE, RST stream", + CURL_TRC_CF(data, cf, "[%d] premature DATA_DONE, RST stream", stream->id); if(!nghttp2_submit_rst_stream(ctx->h2, NGHTTP2_FLAG_NONE, stream->id, NGHTTP2_STREAM_CLOSED)) @@ -364,8 +364,12 @@ static ssize_t nw_out_writer(void *writer_ctx, { struct Curl_cfilter *cf = writer_ctx; struct Curl_easy *data = CF_DATA_CURRENT(cf); + ssize_t nwritten; - return Curl_conn_cf_send(cf->next, data, (const char *)buf, buflen, err); + nwritten = Curl_conn_cf_send(cf->next, data, (const char *)buf, buflen, err); + if(nwritten > 0) + CURL_TRC_CF(data, cf, "[0] egress: wrote %zd bytes", nwritten); + return nwritten; } static ssize_t send_callback(nghttp2_session *h2, @@ -373,6 +377,10 @@ static ssize_t send_callback(nghttp2_session *h2, void *userp); static int on_frame_recv(nghttp2_session *session, const nghttp2_frame *frame, void *userp); +#ifndef CURL_DISABLE_VERBOSE_STRINGS +static int on_frame_send(nghttp2_session *session, const nghttp2_frame *frame, + void *userp); +#endif static int on_data_chunk_recv(nghttp2_session *session, uint8_t flags, int32_t stream_id, const uint8_t *mem, size_t len, void *userp); @@ -415,6 +423,9 @@ static CURLcode cf_h2_ctx_init(struct Curl_cfilter *cf, nghttp2_session_callbacks_set_send_callback(cbs, send_callback); nghttp2_session_callbacks_set_on_frame_recv_callback(cbs, on_frame_recv); +#ifndef CURL_DISABLE_VERBOSE_STRINGS + nghttp2_session_callbacks_set_on_frame_send_callback(cbs, on_frame_send); +#endif nghttp2_session_callbacks_set_on_data_chunk_recv_callback( cbs, on_data_chunk_recv); nghttp2_session_callbacks_set_on_stream_close_callback(cbs, on_stream_close); @@ -463,6 +474,7 @@ static CURLcode cf_h2_ctx_init(struct Curl_cfilter *cf, stream->id); DEBUGASSERT(0); } + CURL_TRC_CF(data, cf, "created session via Upgrade"); } else { nghttp2_settings_entry iv[H2_SETTINGS_IV_LEN]; @@ -490,6 +502,8 @@ static CURLcode cf_h2_ctx_init(struct Curl_cfilter *cf, /* all set, traffic will be send on connect */ result = CURLE_OK; + CURL_TRC_CF(data, cf, "[0] created h2 session%s", + via_h1_upgrade? " (via h1 upgrade)" : ""); out: if(cbs) @@ -647,7 +661,6 @@ static CURLcode nw_out_flush(struct Curl_cfilter *cf, } return result; } - CURL_TRC_CF(data, cf, "nw send buffer flushed"); return Curl_bufq_is_empty(&ctx->outbufq)? CURLE_OK: CURLE_AGAIN; } @@ -839,7 +852,7 @@ static int push_promise(struct Curl_cfilter *cf, struct cf_h2_ctx *ctx = cf->ctx; int rv; /* one of the CURL_PUSH_* defines */ - CURL_TRC_CF(data, cf, "[h2sid=%d] PUSH_PROMISE received", + CURL_TRC_CF(data, cf, "[%d] PUSH_PROMISE received", frame->promised_stream_id); if(data->multi->push_cb) { struct stream_ctx *stream; @@ -968,16 +981,15 @@ static CURLcode on_stream_frame(struct Curl_cfilter *cf, int rv; if(!stream) { - CURL_TRC_CF(data, cf, "[h2sid=%d] No proto pointer", stream_id); + CURL_TRC_CF(data, cf, "[%d] No stream_ctx set", stream_id); return CURLE_FAILED_INIT; } switch(frame->hd.type) { case NGHTTP2_DATA: rbuflen = Curl_bufq_len(&stream->recvbuf); - CURL_TRC_CF(data, cf, "[h2sid=%d] FRAME[DATA len=%zu pad=%zu], " - "buffered=%zu, window=%d/%d", - stream_id, frame->hd.length, frame->data.padlen, rbuflen, + CURL_TRC_CF(data, cf, "[%d] DATA, buffered=%zu, window=%d/%d", + stream_id, rbuflen, nghttp2_session_get_stream_effective_recv_data_length( ctx->h2, stream->id), nghttp2_session_get_stream_effective_local_window_size( @@ -1010,7 +1022,6 @@ static CURLcode on_stream_frame(struct Curl_cfilter *cf, } break; case NGHTTP2_HEADERS: - CURL_TRC_CF(data, cf, "[h2sid=%d] FRAME[HEADERS]", stream_id); if(stream->bodystarted) { /* Only valid HEADERS after body started is trailer HEADERS. We buffer them in on_header callback. */ @@ -1033,12 +1044,9 @@ static CURLcode on_stream_frame(struct Curl_cfilter *cf, if(result) return result; - CURL_TRC_CF(data, cf, "[h2sid=%d] %zu header bytes", - stream_id, Curl_bufq_len(&stream->recvbuf)); drain_stream(cf, data, stream); break; case NGHTTP2_PUSH_PROMISE: - CURL_TRC_CF(data, cf, "[h2sid=%d] FRAME[PUSH_PROMISE]", stream_id); rv = push_promise(cf, data, &frame->push_promise); if(rv) { /* deny! */ DEBUGASSERT((rv > CURL_PUSH_OK) && (rv <= CURL_PUSH_ERROROUT)); @@ -1048,14 +1056,13 @@ static CURLcode on_stream_frame(struct Curl_cfilter *cf, if(nghttp2_is_fatal(rv)) return CURLE_SEND_ERROR; else if(rv == CURL_PUSH_ERROROUT) { - CURL_TRC_CF(data, cf, "[h2sid=%d] fail in PUSH_PROMISE received", + CURL_TRC_CF(data, cf, "[%d] fail in PUSH_PROMISE received", stream_id); return CURLE_RECV_ERROR; } } break; case NGHTTP2_RST_STREAM: - CURL_TRC_CF(data, cf, "[h2sid=%d] FRAME[RST]", stream_id); stream->closed = TRUE; stream->reset = TRUE; stream->send_closed = TRUE; @@ -1063,22 +1070,110 @@ static CURLcode on_stream_frame(struct Curl_cfilter *cf, drain_stream(cf, data, stream); break; case NGHTTP2_WINDOW_UPDATE: - CURL_TRC_CF(data, cf, "[h2sid=%d] FRAME[WINDOW_UPDATE]", stream_id); if((data->req.keepon & KEEP_SEND_HOLD) && (data->req.keepon & KEEP_SEND)) { data->req.keepon &= ~KEEP_SEND_HOLD; drain_stream(cf, data, stream); - CURL_TRC_CF(data, cf, "[h2sid=%d] un-holding after win update", + CURL_TRC_CF(data, cf, "[%d] un-holding after win update", stream_id); } break; default: - CURL_TRC_CF(data, cf, "[h2sid=%d] FRAME[%x]", stream_id, frame->hd.type); break; } return CURLE_OK; } +#ifndef CURL_DISABLE_VERBOSE_STRINGS +static int fr_print(const nghttp2_frame *frame, char *buffer, size_t blen) +{ + switch(frame->hd.type) { + case NGHTTP2_DATA: { + return msnprintf(buffer, blen, + "FRAME[DATA, len=%d, eos=%d, padlen=%d]", + (int)frame->hd.length, + !!(frame->hd.flags & NGHTTP2_FLAG_END_STREAM), + (int)frame->data.padlen); + } + case NGHTTP2_HEADERS: { + return msnprintf(buffer, blen, + "FRAME[HEADERS, len=%d, hend=%d, eos=%d]", + (int)frame->hd.length, + !!(frame->hd.flags & NGHTTP2_FLAG_END_HEADERS), + !!(frame->hd.flags & NGHTTP2_FLAG_END_STREAM)); + } + case NGHTTP2_PRIORITY: { + return msnprintf(buffer, blen, + "FRAME[PRIORITY, len=%d, flags=%d]", + (int)frame->hd.length, frame->hd.flags); + } + case NGHTTP2_RST_STREAM: { + return msnprintf(buffer, blen, + "FRAME[RST_STREAM, len=%d, flags=%d]", + (int)frame->hd.length, frame->hd.flags); + } + case NGHTTP2_SETTINGS: { + if(frame->hd.flags & NGHTTP2_FLAG_ACK) { + return msnprintf(buffer, blen, "FRAME[SETTINGS, ack=1]"); + } + return msnprintf(buffer, blen, + "FRAME[SETTINGS, len=%d]", (int)frame->hd.length); + } + case NGHTTP2_PUSH_PROMISE: { + return msnprintf(buffer, blen, + "FRAME[PUSH_PROMISE, len=%d, hend=%d]", + (int)frame->hd.length, + !!(frame->hd.flags & NGHTTP2_FLAG_END_HEADERS)); + } + case NGHTTP2_PING: { + return msnprintf(buffer, blen, + "FRAME[PING, len=%d, ack=%d]", + (int)frame->hd.length, + frame->hd.flags&NGHTTP2_FLAG_ACK); + } + case NGHTTP2_GOAWAY: { + char scratch[128]; + size_t s_len = sizeof(scratch)/sizeof(scratch[0]); + size_t len = (frame->goaway.opaque_data_len < s_len)? + frame->goaway.opaque_data_len : s_len-1; + if(len) + memcpy(scratch, frame->goaway.opaque_data, len); + scratch[len] = '\0'; + return msnprintf(buffer, blen, "FRAME[GOAWAY, error=%d, reason='%s', " + "last_stream=%d]", frame->goaway.error_code, + scratch, frame->goaway.last_stream_id); + } + case NGHTTP2_WINDOW_UPDATE: { + return msnprintf(buffer, blen, + "FRAME[WINDOW_UPDATE, incr=%d]", + frame->window_update.window_size_increment); + } + default: + return msnprintf(buffer, blen, "FRAME[%d, len=%d, flags=%d]", + frame->hd.type, (int)frame->hd.length, + frame->hd.flags); + } +} + +static int on_frame_send(nghttp2_session *session, const nghttp2_frame *frame, + void *userp) +{ + struct Curl_cfilter *cf = userp; + struct Curl_easy *data = CF_DATA_CURRENT(cf); + + (void)session; + DEBUGASSERT(data); + if(data && Curl_trc_cf_is_verbose(cf, data)) { + char buffer[256]; + int len; + len = fr_print(frame, buffer, (sizeof(buffer)/sizeof(buffer[0]))-1); + buffer[len] = 0; + CURL_TRC_CF(data, cf, "[%d] -> %s", frame->hd.stream_id, buffer); + } + return 0; +} +#endif /* !CURL_DISABLE_VERBOSE_STRINGS */ + static int on_frame_recv(nghttp2_session *session, const nghttp2_frame *frame, void *userp) { @@ -1088,40 +1183,51 @@ static int on_frame_recv(nghttp2_session *session, const nghttp2_frame *frame, int32_t stream_id = frame->hd.stream_id; DEBUGASSERT(data); +#ifndef CURL_DISABLE_VERBOSE_STRINGS + if(Curl_trc_cf_is_verbose(cf, data)) { + char buffer[256]; + int len; + len = fr_print(frame, buffer, (sizeof(buffer)/sizeof(buffer[0]))-1); + buffer[len] = 0; + CURL_TRC_CF(data, cf, "[%d] <- %s",frame->hd.stream_id, buffer); + } +#endif /* !CURL_DISABLE_VERBOSE_STRINGS */ + if(!stream_id) { /* stream ID zero is for connection-oriented stuff */ DEBUGASSERT(data); switch(frame->hd.type) { case NGHTTP2_SETTINGS: { - uint32_t max_conn = ctx->max_concurrent_streams; - CURL_TRC_CF(data, cf, "FRAME[SETTINGS]"); - ctx->max_concurrent_streams = nghttp2_session_get_remote_settings( - session, NGHTTP2_SETTINGS_MAX_CONCURRENT_STREAMS); - ctx->enable_push = nghttp2_session_get_remote_settings( - session, NGHTTP2_SETTINGS_ENABLE_PUSH) != 0; - CURL_TRC_CF(data, cf, "MAX_CONCURRENT_STREAMS == %d", - ctx->max_concurrent_streams); - CURL_TRC_CF(data, cf, "ENABLE_PUSH == %s", - ctx->enable_push ? "TRUE" : "false"); - if(data && max_conn != ctx->max_concurrent_streams) { - /* only signal change if the value actually changed */ - CURL_TRC_CF(data, cf, "MAX_CONCURRENT_STREAMS now %u", + if(!(frame->hd.flags & NGHTTP2_FLAG_ACK)) { + uint32_t max_conn = ctx->max_concurrent_streams; + ctx->max_concurrent_streams = nghttp2_session_get_remote_settings( + session, NGHTTP2_SETTINGS_MAX_CONCURRENT_STREAMS); + ctx->enable_push = nghttp2_session_get_remote_settings( + session, NGHTTP2_SETTINGS_ENABLE_PUSH) != 0; + CURL_TRC_CF(data, cf, "[0] MAX_CONCURRENT_STREAMS: %d", ctx->max_concurrent_streams); - Curl_multi_connchanged(data->multi); - } - /* Since the initial stream window is 64K, a request might be on HOLD, - * due to exhaustion. The (initial) SETTINGS may announce a much larger - * window and *assume* that we treat this like a WINDOW_UPDATE. Some - * servers send an explicit WINDOW_UPDATE, but not all seem to do that. - * To be safe, we UNHOLD a stream in order not to stall. */ - if((data->req.keepon & KEEP_SEND_HOLD) && - (data->req.keepon & KEEP_SEND)) { - struct stream_ctx *stream = H2_STREAM_CTX(data); - data->req.keepon &= ~KEEP_SEND_HOLD; - if(stream) { - drain_stream(cf, data, stream); - CURL_TRC_CF(data, cf, "[h2sid=%d] un-holding after SETTINGS", - stream_id); + CURL_TRC_CF(data, cf, "[0] ENABLE_PUSH: %s", + ctx->enable_push ? "TRUE" : "false"); + if(data && max_conn != ctx->max_concurrent_streams) { + /* only signal change if the value actually changed */ + CURL_TRC_CF(data, cf, "[0] notify MAX_CONCURRENT_STREAMS: %u", + ctx->max_concurrent_streams); + Curl_multi_connchanged(data->multi); + } + /* Since the initial stream window is 64K, a request might be on HOLD, + * due to exhaustion. The (initial) SETTINGS may announce a much larger + * window and *assume* that we treat this like a WINDOW_UPDATE. Some + * servers send an explicit WINDOW_UPDATE, but not all seem to do that. + * To be safe, we UNHOLD a stream in order not to stall. */ + if((data->req.keepon & KEEP_SEND_HOLD) && + (data->req.keepon & KEEP_SEND)) { + struct stream_ctx *stream = H2_STREAM_CTX(data); + data->req.keepon &= ~KEEP_SEND_HOLD; + if(stream) { + drain_stream(cf, data, stream); + CURL_TRC_CF(data, cf, "[%d] un-holding after SETTINGS", + stream_id); + } } } break; @@ -1131,25 +1237,20 @@ static int on_frame_recv(nghttp2_session *session, const nghttp2_frame *frame, ctx->goaway_error = frame->goaway.error_code; ctx->last_stream_id = frame->goaway.last_stream_id; if(data) { - CURL_TRC_CF(data, cf, "FRAME[GOAWAY, error=%d, last_stream=%u]", - ctx->goaway_error, ctx->last_stream_id); infof(data, "received GOAWAY, error=%d, last_stream=%u", ctx->goaway_error, ctx->last_stream_id); Curl_multi_connchanged(data->multi); } break; - case NGHTTP2_WINDOW_UPDATE: - CURL_TRC_CF(data, cf, "FRAME[WINDOW_UPDATE]"); - break; default: - CURL_TRC_CF(data, cf, "recv frame %x on 0", frame->hd.type); + break; } return 0; } data_s = nghttp2_session_get_stream_user_data(session, stream_id); if(!data_s) { - CURL_TRC_CF(data, cf, "[h2sid=%d] No Curl_easy associated", stream_id); + CURL_TRC_CF(data, cf, "[%d] No Curl_easy associated", stream_id); return 0; } @@ -1176,7 +1277,7 @@ static int on_data_chunk_recv(nghttp2_session *session, uint8_t flags, /* Receiving a Stream ID not in the hash should not happen - unless we have aborted a transfer artificially and there were more data in the pipeline. Silently ignore. */ - CURL_TRC_CF(CF_DATA_CURRENT(cf), cf, "[h2sid=%d] Data for unknown", + CURL_TRC_CF(CF_DATA_CURRENT(cf), cf, "[%d] Data for unknown", stream_id); /* consumed explicitly as no one will read it */ nghttp2_session_consume(session, stream_id, len); @@ -1219,8 +1320,6 @@ static int on_stream_close(nghttp2_session *session, int32_t stream_id, return 0; } stream = H2_STREAM_CTX(data_s); - CURL_TRC_CF(data_s, cf, "[h2sid=%d] on_stream_close(), %s (err %d)", - stream_id, nghttp2_http2_strerror(error_code), error_code); if(!stream) return NGHTTP2_ERR_CALLBACK_FAILURE; @@ -1230,6 +1329,11 @@ static int on_stream_close(nghttp2_session *session, int32_t stream_id, stream->reset = TRUE; data_s->req.keepon &= ~KEEP_SEND_HOLD; + if(stream->error) + CURL_TRC_CF(data_s, cf, "[%d] RESET: %s (err %d)", + stream_id, nghttp2_http2_strerror(error_code), error_code); + else + CURL_TRC_CF(data_s, cf, "[%d] CLOSED", stream_id); drain_stream(cf, data_s, stream); /* remove `data_s` from the nghttp2 stream */ @@ -1239,7 +1343,6 @@ static int on_stream_close(nghttp2_session *session, int32_t stream_id, stream_id); DEBUGASSERT(0); } - CURL_TRC_CF(data_s, cf, "[h2sid=%d] closed now", stream_id); return 0; } @@ -1256,8 +1359,6 @@ static int on_begin_headers(nghttp2_session *session, return 0; } - CURL_TRC_CF(data_s, cf, "on_begin_headers() was called"); - if(frame->hd.type != NGHTTP2_HEADERS) { return 0; } @@ -1363,7 +1464,7 @@ static int on_header(nghttp2_session *session, const nghttp2_frame *frame, if(stream->bodystarted) { /* This is a trailer */ - CURL_TRC_CF(data_s, cf, "[h2sid=%d] trailer: %.*s: %.*s", + CURL_TRC_CF(data_s, cf, "[%d] trailer: %.*s: %.*s", stream->id, (int)namelen, name, (int)valuelen, value); result = Curl_dynhds_add(&stream->resp_trailers, (const char *)name, namelen, @@ -1401,7 +1502,7 @@ static int on_header(nghttp2_session *session, const nghttp2_frame *frame, if(CF_DATA_CURRENT(cf) != data_s) Curl_expire(data_s, 0, EXPIRE_RUN_NOW); - CURL_TRC_CF(data_s, cf, "[h2sid=%d] status: HTTP/2 %03d", + CURL_TRC_CF(data_s, cf, "[%d] status: HTTP/2 %03d", stream->id, stream->status_code); return 0; } @@ -1425,7 +1526,7 @@ static int on_header(nghttp2_session *session, const nghttp2_frame *frame, if(CF_DATA_CURRENT(cf) != data_s) Curl_expire(data_s, 0, EXPIRE_RUN_NOW); - CURL_TRC_CF(data_s, cf, "[h2sid=%d] header: %.*s: %.*s", + CURL_TRC_CF(data_s, cf, "[%d] header: %.*s: %.*s", stream->id, (int)namelen, name, (int)valuelen, value); return 0; /* 0 is successful */ @@ -1472,7 +1573,7 @@ static ssize_t req_body_read_callback(nghttp2_session *session, if(nread > 0 && stream->upload_left != -1) stream->upload_left -= nread; - CURL_TRC_CF(data_s, cf, "[h2sid=%d] req_body_read(len=%zu) left=%" + CURL_TRC_CF(data_s, cf, "[%d] req_body_read(len=%zu) left=%" CURL_FORMAT_CURL_OFF_T " -> %zd, %d", stream_id, length, stream->upload_left, nread, result); @@ -1547,7 +1648,7 @@ static CURLcode http2_data_done_send(struct Curl_cfilter *cf, if(!ctx || !ctx->h2 || !stream) goto out; - CURL_TRC_CF(data, cf, "[h2sid=%d] data done send", stream->id); + CURL_TRC_CF(data, cf, "[%d] data done send", stream->id); if(!stream->send_closed) { stream->send_closed = TRUE; if(stream->upload_left) { @@ -1572,7 +1673,7 @@ static ssize_t http2_handle_stream_close(struct Curl_cfilter *cf, ssize_t rv = 0; if(stream->error == NGHTTP2_REFUSED_STREAM) { - CURL_TRC_CF(data, cf, "[h2sid=%d] REFUSED_STREAM, try again on a new " + CURL_TRC_CF(data, cf, "[%d] REFUSED_STREAM, try again on a new " "connection", stream->id); connclose(cf->conn, "REFUSED_STREAM"); /* don't use this anymore */ data->state.refused_stream = TRUE; @@ -1691,7 +1792,7 @@ static CURLcode h2_progress_egress(struct Curl_cfilter *cf, nghttp2_priority_spec pri_spec; h2_pri_spec(data, &pri_spec); - CURL_TRC_CF(data, cf, "[h2sid=%d] Queuing PRIORITY", stream->id); + CURL_TRC_CF(data, cf, "[%d] Queuing PRIORITY", stream->id); DEBUGASSERT(stream->id != -1); rv = nghttp2_submit_priority(ctx->h2, NGHTTP2_FLAG_NONE, stream->id, &pri_spec); @@ -1723,8 +1824,6 @@ static ssize_t stream_recv(struct Curl_cfilter *cf, struct Curl_easy *data, if(!Curl_bufq_is_empty(&stream->recvbuf)) { nread = Curl_bufq_read(&stream->recvbuf, (unsigned char *)buf, len, err); - CURL_TRC_CF(data, cf, "recvbuf read(len=%zu) -> %zd, %d", - len, nread, *err); if(nread < 0) goto out; DEBUGASSERT(nread > 0); @@ -1732,13 +1831,13 @@ static ssize_t stream_recv(struct Curl_cfilter *cf, struct Curl_easy *data, if(nread < 0) { if(stream->closed) { - CURL_TRC_CF(data, cf, "[h2sid=%d] returning CLOSE", stream->id); + CURL_TRC_CF(data, cf, "[%d] returning CLOSE", stream->id); nread = http2_handle_stream_close(cf, data, stream, err); } else if(stream->reset || (ctx->conn_closed && Curl_bufq_is_empty(&ctx->inbufq)) || (ctx->goaway && ctx->last_stream_id < stream->id)) { - CURL_TRC_CF(data, cf, "[h2sid=%d] returning ERR", stream->id); + CURL_TRC_CF(data, cf, "[%d] returning ERR", stream->id); *err = stream->bodystarted? CURLE_PARTIAL_FILE : CURLE_RECV_ERROR; nread = -1; } @@ -1749,7 +1848,9 @@ static ssize_t stream_recv(struct Curl_cfilter *cf, struct Curl_easy *data, } out: - CURL_TRC_CF(data, cf, "stream_recv(len=%zu) -> %zd, %d", len, nread, *err); + if(nread < 0 && *err != CURLE_AGAIN) + CURL_TRC_CF(data, cf, "[%d] stream_recv(len=%zu) -> %zd, %d", + stream->id, len, nread, *err); return nread; } @@ -1793,9 +1894,14 @@ static CURLcode h2_progress_ingress(struct Curl_cfilter *cf, break; } else if(nread == 0) { + CURL_TRC_CF(data, cf, "[0] ingress: connection closed"); ctx->conn_closed = TRUE; break; } + else { + CURL_TRC_CF(data, cf, "[0] ingress: read %zd bytes", + nread); + } if(h2_process_pending_input(cf, data, &result)) return result; @@ -1862,7 +1968,7 @@ static ssize_t cf_h2_recv(struct Curl_cfilter *cf, struct Curl_easy *data, } if(stream->closed) { - CURL_TRC_CF(data, cf, "[h2sid=%d] closed stream, set drain", stream->id); + CURL_TRC_CF(data, cf, "[%d] DRAIN closed stream", stream->id); drain_stream(cf, data, stream); } } @@ -1873,7 +1979,7 @@ out: *err = result; nread = -1; } - CURL_TRC_CF(data, cf, "[h2sid=%d] cf_recv(len=%zu) -> %zd %d, " + CURL_TRC_CF(data, cf, "[%d] cf_recv(len=%zu) -> %zd %d, " "buffered=%zu, window=%d/%d, connection %d/%d", stream->id, len, nread, *err, Curl_bufq_len(&stream->recvbuf), @@ -1942,29 +2048,9 @@ static ssize_t h2_submit(struct stream_ctx **pstream, nva[i].flags = NGHTTP2_NV_FLAG_NONE; } -#define MAX_ACC 60000 /* <64KB to account for some overhead */ - { - size_t acc = 0; - - for(i = 0; i < nheader; ++i) { - acc += nva[i].namelen + nva[i].valuelen; - - infof(data, "h2 [%.*s: %.*s]", - (int)nva[i].namelen, nva[i].name, - (int)nva[i].valuelen, nva[i].value); - } - - if(acc > MAX_ACC) { - infof(data, "http_request: Warning: The cumulative length of all " - "headers exceeds %d bytes and that could cause the " - "stream to be rejected.", MAX_ACC); - } - } - h2_pri_spec(data, &pri_spec); - - CURL_TRC_CF(data, cf, "send request allowed %d", - nghttp2_session_check_request_allowed(ctx->h2)); + if(!nghttp2_session_check_request_allowed(ctx->h2)) + CURL_TRC_CF(data, cf, "send request NOT allowed (via nghttp2)"); switch(data->state.httpreq) { case HTTPREQ_POST: @@ -1988,8 +2074,6 @@ static ssize_t h2_submit(struct stream_ctx **pstream, NULL, data); } - Curl_safefree(nva); - if(stream_id < 0) { CURL_TRC_CF(data, cf, "send: nghttp2_submit_request error (%s)%u", nghttp2_strerror(stream_id), stream_id); @@ -1998,9 +2082,27 @@ static ssize_t h2_submit(struct stream_ctx **pstream, goto out; } - CURL_TRC_CF(data, cf, "[h2sid=%d] cf_send(len=%zu) submit %s", - stream_id, len, data->state.url); - infof(data, "Using Stream ID: %u", stream_id); +#define MAX_ACC 60000 /* <64KB to account for some overhead */ + if(Curl_trc_is_verbose(data)) { + size_t acc = 0; + + infof(data, "[HTTP/2] [%d] OPENED stream for %s", + stream_id, data->state.url); + for(i = 0; i < nheader; ++i) { + acc += nva[i].namelen + nva[i].valuelen; + + infof(data, "[HTTP/2] [%d] [%.*s: %.*s]", stream_id, + (int)nva[i].namelen, nva[i].name, + (int)nva[i].valuelen, nva[i].value); + } + + if(acc > MAX_ACC) { + infof(data, "[HTTP/2] Warning: The cumulative length of all " + "headers exceeds %d bytes and that could cause the " + "stream to be rejected.", MAX_ACC); + } + } + stream->id = stream_id; stream->local_window_size = H2_STREAM_WINDOW_SIZE; if(data->set.max_recv_speed) { @@ -2031,8 +2133,9 @@ static ssize_t h2_submit(struct stream_ctx **pstream, } out: - CURL_TRC_CF(data, cf, "[h2sid=%d] submit -> %zd, %d", + CURL_TRC_CF(data, cf, "[%d] submit -> %zd, %d", stream? stream->id : -1, nwritten, *err); + Curl_safefree(nva); *pstream = stream; Curl_h1_req_parse_free(&h1); Curl_dynhds_free(&h2_headers); @@ -2144,7 +2247,7 @@ static ssize_t cf_h2_send(struct Curl_cfilter *cf, struct Curl_easy *data, /* H2 flow window exhaustion. We need to HOLD upload until we get * a WINDOW_UPDATE from the server. */ data->req.keepon |= KEEP_SEND_HOLD; - CURL_TRC_CF(data, cf, "[h2sid=%d] holding send as remote flow " + CURL_TRC_CF(data, cf, "[%d] holding send as remote flow " "window is exhausted", stream->id); } @@ -2152,7 +2255,7 @@ static ssize_t cf_h2_send(struct Curl_cfilter *cf, struct Curl_easy *data, * We have unwritten state that needs us being invoked again and EAGAIN * is the only way to ensure that. */ stream->upload_blocked_len = nwritten; - CURL_TRC_CF(data, cf, "[h2sid=%d] cf_send(len=%zu) BLOCK: win %u/%zu " + CURL_TRC_CF(data, cf, "[%d] cf_send(len=%zu) BLOCK: win %u/%zu " "blocked_len=%zu", stream->id, len, nghttp2_session_get_remote_window_size(ctx->h2), rwin, @@ -2176,7 +2279,7 @@ static ssize_t cf_h2_send(struct Curl_cfilter *cf, struct Curl_easy *data, out: if(stream) { - CURL_TRC_CF(data, cf, "[h2sid=%d] cf_send(len=%zu) -> %zd, %d, " + CURL_TRC_CF(data, cf, "[%d] cf_send(len=%zu) -> %zd, %d, " "upload_left=%" CURL_FORMAT_CURL_OFF_T ", " "h2 windows %d-%d (stream-conn), " "buffers %zu-%zu (stream-conn)",