http2: cleanup trace messages
- more compact format with bracketed stream id - all frames traced in and out Closes #11592
This commit is contained in:
Stefan Eissing
Daniel Stenberg
parent
03eba3c8b2
commit
fbacb14c4c
311
lib/http2.c
311
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)",
|
||||
|
||||
Loading…
Reference in New Issue
Block a user