http2: polish things around POST

- added test cases for various code paths
- fixed handling of blocked write when stream had
  been closed inbetween attempts
- re-enabled DEBUGASSERT on send with smaller data size

- in debug builds, environment variables can be set to simulate a slow
  network when sending data. cf-socket.c and vquic.c support
  * CURL_DBG_SOCK_WBLOCK: percentage of send() calls that should be
    answered with a EAGAIN. TCP/UNIX sockets.
    This is chosen randomly.
  * CURL_DBG_SOCK_WPARTIAL: percentage of data that shall be written
    to the network. TCP/UNIX sockets.
    Example: 80 means a send with 1000 bytes would only send 800
    This is applied to every send.
  * CURL_DBG_QUIC_WBLOCK: percentage of send() calls that should be
    answered with EAGAIN. QUIC only.
    This is chosen randomly.

Closes #11756
This commit is contained in:
Stefan Eissing 2023-08-29 13:08:35 +02:00 committed by Daniel Stenberg
parent c9260cf9fe
commit 331b89a319
No known key found for this signature in database
GPG key ID: 5CC908FDB71E12C2
23 changed files with 897 additions and 164 deletions

View file

@ -35,6 +35,7 @@
#include "dynbuf.h"
#include "dynhds.h"
#include "http1.h"
#include "http2.h"
#include "http_proxy.h"
#include "multiif.h"
#include "cf-h2-proxy.h"
@ -146,29 +147,30 @@ static void h2_tunnel_go_state(struct Curl_cfilter *cf,
/* entering this one */
switch(new_state) {
case H2_TUNNEL_INIT:
CURL_TRC_CF(data, cf, "new tunnel state 'init'");
CURL_TRC_CF(data, cf, "[%d] new tunnel state 'init'", ts->stream_id);
tunnel_stream_clear(ts);
break;
case H2_TUNNEL_CONNECT:
CURL_TRC_CF(data, cf, "new tunnel state 'connect'");
CURL_TRC_CF(data, cf, "[%d] new tunnel state 'connect'", ts->stream_id);
ts->state = H2_TUNNEL_CONNECT;
break;
case H2_TUNNEL_RESPONSE:
CURL_TRC_CF(data, cf, "new tunnel state 'response'");
CURL_TRC_CF(data, cf, "[%d] new tunnel state 'response'", ts->stream_id);
ts->state = H2_TUNNEL_RESPONSE;
break;
case H2_TUNNEL_ESTABLISHED:
CURL_TRC_CF(data, cf, "new tunnel state 'established'");
CURL_TRC_CF(data, cf, "[%d] new tunnel state 'established'",
ts->stream_id);
infof(data, "CONNECT phase completed");
data->state.authproxy.done = TRUE;
data->state.authproxy.multipass = FALSE;
/* FALLTHROUGH */
case H2_TUNNEL_FAILED:
if(new_state == H2_TUNNEL_FAILED)
CURL_TRC_CF(data, cf, "new tunnel state 'failed'");
CURL_TRC_CF(data, cf, "[%d] new tunnel state 'failed'", ts->stream_id);
ts->state = new_state;
/* If a proxy-authorization header was used for the proxy, then we should
make sure that it isn't accidentally used for the document request
@ -231,8 +233,8 @@ static void drain_tunnel(struct Curl_cfilter *cf,
bits = CURL_CSELECT_IN;
if(!tunnel->closed && !tunnel->reset && tunnel->upload_blocked_len)
bits |= CURL_CSELECT_OUT;
if(data->state.dselect_bits != bits) {
CURL_TRC_CF(data, cf, "[h2sid=%d] DRAIN dselect_bits=%x",
if(data->state.dselect_bits != bits || 1) {
CURL_TRC_CF(data, cf, "[%d] DRAIN dselect_bits=%x",
tunnel->stream_id, bits);
data->state.dselect_bits = bits;
Curl_expire(data, 0, EXPIRE_RUN_NOW);
@ -249,7 +251,7 @@ static ssize_t proxy_nw_in_reader(void *reader_ctx,
if(cf) {
struct Curl_easy *data = CF_DATA_CURRENT(cf);
nread = Curl_conn_cf_recv(cf->next, data, (char *)buf, buflen, err);
CURL_TRC_CF(data, cf, "nw_in_reader(len=%zu) -> %zd, %d",
CURL_TRC_CF(data, cf, "[0] nw_in_reader(len=%zu) -> %zd, %d",
buflen, nread, *err);
}
else {
@ -269,7 +271,7 @@ static ssize_t proxy_h2_nw_out_writer(void *writer_ctx,
struct Curl_easy *data = CF_DATA_CURRENT(cf);
nwritten = Curl_conn_cf_send(cf->next, data, (const char *)buf, buflen,
err);
CURL_TRC_CF(data, cf, "nw_out_writer(len=%zu) -> %zd, %d",
CURL_TRC_CF(data, cf, "[0] nw_out_writer(len=%zu) -> %zd, %d",
buflen, nwritten, *err);
}
else {
@ -306,6 +308,10 @@ static ssize_t on_session_send(nghttp2_session *h2,
static int proxy_h2_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 proxy_h2_on_stream_close(nghttp2_session *session,
int32_t stream_id,
uint32_t error_code, void *userp);
@ -348,6 +354,9 @@ static CURLcode cf_h2_proxy_ctx_init(struct Curl_cfilter *cf,
nghttp2_session_callbacks_set_send_callback(cbs, on_session_send);
nghttp2_session_callbacks_set_on_frame_recv_callback(
cbs, proxy_h2_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, tunnel_recv_callback);
nghttp2_session_callbacks_set_on_stream_close_callback(
@ -395,7 +404,7 @@ static CURLcode cf_h2_proxy_ctx_init(struct Curl_cfilter *cf,
out:
if(cbs)
nghttp2_session_callbacks_del(cbs);
CURL_TRC_CF(data, cf, "init proxy ctx -> %d", result);
CURL_TRC_CF(data, cf, "[0] init proxy ctx -> %d", result);
return result;
}
@ -420,13 +429,13 @@ static CURLcode proxy_h2_nw_out_flush(struct Curl_cfilter *cf,
&result);
if(nwritten < 0) {
if(result == CURLE_AGAIN) {
CURL_TRC_CF(data, cf, "flush nw send buffer(%zu) -> EAGAIN",
CURL_TRC_CF(data, cf, "[0] flush nw send buffer(%zu) -> EAGAIN",
Curl_bufq_len(&ctx->outbufq));
ctx->nw_out_blocked = 1;
}
return result;
}
CURL_TRC_CF(data, cf, "nw send buffer flushed");
CURL_TRC_CF(data, cf, "[0] nw send buffer flushed");
return Curl_bufq_is_empty(&ctx->outbufq)? CURLE_OK: CURLE_AGAIN;
}
@ -447,7 +456,7 @@ static int proxy_h2_process_pending_input(struct Curl_cfilter *cf,
while(Curl_bufq_peek(&ctx->inbufq, &buf, &blen)) {
rv = nghttp2_session_mem_recv(ctx->h2, (const uint8_t *)buf, blen);
CURL_TRC_CF(data, cf, "fed %zu bytes from nw to nghttp2 -> %zd", blen, rv);
CURL_TRC_CF(data, cf, "[0] %zu bytes to nghttp2 -> %zd", blen, rv);
if(rv < 0) {
failf(data,
"process_pending_input: nghttp2_session_mem_recv() returned "
@ -457,11 +466,11 @@ static int proxy_h2_process_pending_input(struct Curl_cfilter *cf,
}
Curl_bufq_skip(&ctx->inbufq, (size_t)rv);
if(Curl_bufq_is_empty(&ctx->inbufq)) {
CURL_TRC_CF(data, cf, "all data in connection buffer processed");
CURL_TRC_CF(data, cf, "[0] all data in connection buffer processed");
break;
}
else {
CURL_TRC_CF(data, cf, "process_pending_input: %zu bytes left "
CURL_TRC_CF(data, cf, "[0] process_pending_input: %zu bytes left "
"in connection buffer", Curl_bufq_len(&ctx->inbufq));
}
}
@ -478,7 +487,7 @@ static CURLcode proxy_h2_progress_ingress(struct Curl_cfilter *cf,
/* Process network input buffer fist */
if(!Curl_bufq_is_empty(&ctx->inbufq)) {
CURL_TRC_CF(data, cf, "Process %zu bytes in connection buffer",
CURL_TRC_CF(data, cf, "[0] process %zu bytes in connection buffer",
Curl_bufq_len(&ctx->inbufq));
if(proxy_h2_process_pending_input(cf, data, &result) < 0)
return result;
@ -492,7 +501,7 @@ static CURLcode proxy_h2_progress_ingress(struct Curl_cfilter *cf,
!Curl_bufq_is_full(&ctx->tunnel.recvbuf)) {
nread = Curl_bufq_slurp(&ctx->inbufq, proxy_nw_in_reader, cf, &result);
CURL_TRC_CF(data, cf, "read %zu bytes nw data -> %zd, %d",
CURL_TRC_CF(data, cf, "[0] read %zu bytes nw data -> %zd, %d",
Curl_bufq_len(&ctx->inbufq), nread, result);
if(nread < 0) {
if(result != CURLE_AGAIN) {
@ -528,7 +537,7 @@ static CURLcode proxy_h2_progress_egress(struct Curl_cfilter *cf,
rv = nghttp2_session_send(ctx->h2);
if(nghttp2_is_fatal(rv)) {
CURL_TRC_CF(data, cf, "nghttp2_session_send error (%s)%d",
CURL_TRC_CF(data, cf, "[0] nghttp2_session_send error (%s)%d",
nghttp2_strerror(rv), rv);
return CURLE_SEND_ERROR;
}
@ -565,6 +574,97 @@ static ssize_t on_session_send(nghttp2_session *h2,
return nwritten;
}
#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, error=%u]",
(int)frame->hd.length, frame->hd.flags,
frame->rst_stream.error_code);
}
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)-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 proxy_h2_on_frame_recv(nghttp2_session *session,
const nghttp2_frame *frame,
void *userp)
@ -576,47 +676,57 @@ static int proxy_h2_on_frame_recv(nghttp2_session *session,
(void)session;
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)-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:
/* we do not do anything with this for now */
/* 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)) {
data->req.keepon &= ~KEEP_SEND_HOLD;
drain_tunnel(cf, data, &ctx->tunnel);
CURL_TRC_CF(data, cf, "[%d] un-holding after SETTINGS",
stream_id);
}
break;
case NGHTTP2_GOAWAY:
infof(data, "recveived GOAWAY, error=%d, last_stream=%u",
frame->goaway.error_code, frame->goaway.last_stream_id);
ctx->goaway = TRUE;
break;
case NGHTTP2_WINDOW_UPDATE:
CURL_TRC_CF(data, cf, "recv frame WINDOW_UPDATE");
break;
default:
CURL_TRC_CF(data, cf, "recv frame %x on 0", frame->hd.type);
break;
}
return 0;
}
if(stream_id != ctx->tunnel.stream_id) {
CURL_TRC_CF(data, cf, "[h2sid=%u] rcvd FRAME not for tunnel", stream_id);
CURL_TRC_CF(data, cf, "[%d] rcvd FRAME not for tunnel", stream_id);
return NGHTTP2_ERR_CALLBACK_FAILURE;
}
switch(frame->hd.type) {
case NGHTTP2_DATA:
/* If body started on this stream, then receiving DATA is illegal. */
CURL_TRC_CF(data, cf, "[h2sid=%u] recv frame DATA", stream_id);
break;
case NGHTTP2_HEADERS:
CURL_TRC_CF(data, cf, "[h2sid=%u] recv frame HEADERS", stream_id);
/* nghttp2 guarantees that :status is received, and we store it to
stream->status_code. Fuzzing has proven this can still be reached
without status code having been set. */
if(!ctx->tunnel.resp)
return NGHTTP2_ERR_CALLBACK_FAILURE;
/* Only final status code signals the end of header */
CURL_TRC_CF(data, cf, "[h2sid=%u] got http status: %d",
CURL_TRC_CF(data, cf, "[%d] got http status: %d",
stream_id, ctx->tunnel.resp->status);
if(!ctx->tunnel.has_final_response) {
if(ctx->tunnel.resp->status / 100 != 1) {
@ -624,26 +734,16 @@ static int proxy_h2_on_frame_recv(nghttp2_session *session,
}
}
break;
case NGHTTP2_PUSH_PROMISE:
CURL_TRC_CF(data, cf, "[h2sid=%u] recv PUSH_PROMISE", stream_id);
return NGHTTP2_ERR_CALLBACK_FAILURE;
case NGHTTP2_RST_STREAM:
CURL_TRC_CF(data, cf, "[h2sid=%u] recv RST", stream_id);
ctx->tunnel.reset = TRUE;
break;
case NGHTTP2_WINDOW_UPDATE:
CURL_TRC_CF(data, cf, "[h2sid=%u] recv WINDOW_UPDATE", stream_id);
if((data->req.keepon & KEEP_SEND_HOLD) &&
(data->req.keepon & KEEP_SEND)) {
data->req.keepon &= ~KEEP_SEND_HOLD;
Curl_expire(data, 0, EXPIRE_RUN_NOW);
CURL_TRC_CF(data, cf, "[h2sid=%u] unpausing after win update",
CURL_TRC_CF(data, cf, "[%d] unpausing after win update",
stream_id);
}
break;
default:
CURL_TRC_CF(data, cf, "[h2sid=%u] recv frame %x",
stream_id, frame->hd.type);
break;
}
return 0;
@ -667,7 +767,7 @@ static int proxy_h2_on_header(nghttp2_session *session,
(void)session;
DEBUGASSERT(stream_id); /* should never be a zero stream ID here */
if(stream_id != ctx->tunnel.stream_id) {
CURL_TRC_CF(data, cf, "[h2sid=%u] header for non-tunnel stream: "
CURL_TRC_CF(data, cf, "[%d] header for non-tunnel stream: "
"%.*s: %.*s", stream_id,
(int)namelen, name, (int)valuelen, value);
return NGHTTP2_ERR_CALLBACK_FAILURE;
@ -697,7 +797,7 @@ static int proxy_h2_on_header(nghttp2_session *session,
return NGHTTP2_ERR_CALLBACK_FAILURE;
resp->prev = ctx->tunnel.resp;
ctx->tunnel.resp = resp;
CURL_TRC_CF(data, cf, "[h2sid=%u] status: HTTP/2 %03d",
CURL_TRC_CF(data, cf, "[%d] status: HTTP/2 %03d",
stream_id, ctx->tunnel.resp->status);
return 0;
}
@ -711,7 +811,7 @@ static int proxy_h2_on_header(nghttp2_session *session,
if(result)
return NGHTTP2_ERR_CALLBACK_FAILURE;
CURL_TRC_CF(data, cf, "[h2sid=%u] header: %.*s: %.*s",
CURL_TRC_CF(data, cf, "[%d] header: %.*s: %.*s",
stream_id, (int)namelen, name, (int)valuelen, value);
return 0; /* 0 is successful */
@ -752,7 +852,7 @@ static ssize_t tunnel_send_callback(nghttp2_session *session,
if(ts->closed && Curl_bufq_is_empty(&ts->sendbuf))
*data_flags = NGHTTP2_DATA_FLAG_EOF;
CURL_TRC_CF(data, cf, "[h2sid=%u] tunnel_send_callback -> %zd",
CURL_TRC_CF(data, cf, "[%d] tunnel_send_callback -> %zd",
ts->stream_id, nread);
return nread;
}
@ -797,7 +897,7 @@ static int proxy_h2_on_stream_close(nghttp2_session *session,
if(stream_id != ctx->tunnel.stream_id)
return 0;
CURL_TRC_CF(data, cf, "[h2sid=%u] proxy_h2_on_stream_close, %s (err %d)",
CURL_TRC_CF(data, cf, "[%d] proxy_h2_on_stream_close, %s (err %d)",
stream_id, nghttp2_http2_strerror(error_code), error_code);
ctx->tunnel.closed = TRUE;
ctx->tunnel.error = error_code;
@ -916,8 +1016,8 @@ static CURLcode submit_CONNECT(struct Curl_cfilter *cf,
result = proxy_h2_submit(&ts->stream_id, cf, data, ctx->h2, req,
NULL, ts, tunnel_send_callback, cf);
if(result) {
CURL_TRC_CF(data, cf, "send: nghttp2_submit_request error (%s)%u",
nghttp2_strerror(ts->stream_id), ts->stream_id);
CURL_TRC_CF(data, cf, "[%d] send, nghttp2_submit_request error: %s",
ts->stream_id, nghttp2_strerror(ts->stream_id));
}
out:
@ -951,7 +1051,7 @@ static CURLcode inspect_response(struct Curl_cfilter *cf,
}
if(auth_reply) {
CURL_TRC_CF(data, cf, "CONNECT: fwd auth header '%s'",
CURL_TRC_CF(data, cf, "[0] CONNECT: fwd auth header '%s'",
auth_reply->value);
result = Curl_http_input_auth(data, ts->resp->status == 407,
auth_reply->value);
@ -982,7 +1082,7 @@ static CURLcode H2_CONNECT(struct Curl_cfilter *cf,
switch(ts->state) {
case H2_TUNNEL_INIT:
/* Prepare the CONNECT request and make a first attempt to send. */
CURL_TRC_CF(data, cf, "CONNECT start for %s", ts->authority);
CURL_TRC_CF(data, cf, "[0] CONNECT start for %s", ts->authority);
result = submit_CONNECT(cf, data, ts);
if(result)
goto out;
@ -1149,7 +1249,7 @@ static ssize_t h2_handle_tunnel_close(struct Curl_cfilter *cf,
ssize_t rv = 0;
if(ctx->tunnel.error == NGHTTP2_REFUSED_STREAM) {
CURL_TRC_CF(data, cf, "[h2sid=%u] REFUSED_STREAM, try again on a new "
CURL_TRC_CF(data, cf, "[%d] REFUSED_STREAM, try again on a new "
"connection", ctx->tunnel.stream_id);
connclose(cf->conn, "REFUSED_STREAM"); /* don't use this anymore */
*err = CURLE_RECV_ERROR; /* trigger Curl_retry_request() later */
@ -1170,7 +1270,8 @@ static ssize_t h2_handle_tunnel_close(struct Curl_cfilter *cf,
*err = CURLE_OK;
rv = 0;
CURL_TRC_CF(data, cf, "handle_tunnel_close -> %zd, %d", rv, *err);
CURL_TRC_CF(data, cf, "[%d] handle_tunnel_close -> %zd, %d",
ctx->tunnel.stream_id, rv, *err);
return rv;
}
@ -1206,8 +1307,8 @@ static ssize_t tunnel_recv(struct Curl_cfilter *cf, struct Curl_easy *data,
}
out:
CURL_TRC_CF(data, cf, "tunnel_recv(len=%zu) -> %zd, %d",
len, nread, *err);
CURL_TRC_CF(data, cf, "[%d] tunnel_recv(len=%zu) -> %zd, %d",
ctx->tunnel.stream_id, len, nread, *err);
return nread;
}
@ -1235,13 +1336,22 @@ static ssize_t cf_h2_proxy_recv(struct Curl_cfilter *cf,
nread = tunnel_recv(cf, data, buf, len, err);
if(nread > 0) {
CURL_TRC_CF(data, cf, "[h2sid=%u] increase window by %zd",
CURL_TRC_CF(data, cf, "[%d] increase window by %zd",
ctx->tunnel.stream_id, nread);
nghttp2_session_consume(ctx->h2, ctx->tunnel.stream_id, (size_t)nread);
}
result = proxy_h2_progress_egress(cf, data);
if(result && result != CURLE_AGAIN) {
if(result == CURLE_AGAIN) {
/* pending data to send, need to be called again. Ideally, we'd
* monitor the socket for POLLOUT, but we might not be in SENDING
* transfer state any longer and are unable to make this happen.
*/
CURL_TRC_CF(data, cf, "[%d] egress blocked, DRAIN",
ctx->tunnel.stream_id);
drain_tunnel(cf, data, &ctx->tunnel);
}
else if(result) {
*err = result;
nread = -1;
}
@ -1253,7 +1363,7 @@ out:
* draining to avoid stalling when no socket events happen. */
drain_tunnel(cf, data, &ctx->tunnel);
}
CURL_TRC_CF(data, cf, "[h2sid=%u] cf_recv(len=%zu) -> %zd %d",
CURL_TRC_CF(data, cf, "[%d] cf_recv(len=%zu) -> %zd %d",
ctx->tunnel.stream_id, len, nread, *err);
CF_DATA_RESTORE(cf, save);
return nread;
@ -1295,6 +1405,7 @@ static ssize_t cf_h2_proxy_send(struct Curl_cfilter *cf,
}
nwritten = (ssize_t)ctx->tunnel.upload_blocked_len;
ctx->tunnel.upload_blocked_len = 0;
*err = CURLE_OK;
}
else {
nwritten = Curl_bufq_write(&ctx->tunnel.sendbuf, buf, len, err);
@ -1352,7 +1463,7 @@ static ssize_t cf_h2_proxy_send(struct Curl_cfilter *cf,
* proxy connection AND to UNHOLD all of them again when the
* window increases.
* We *could* iterate over all data on this conn maybe? */
CURL_TRC_CF(data, cf, "[h2sid=%d] remote flow "
CURL_TRC_CF(data, cf, "[%d] remote flow "
"window is exhausted", ctx->tunnel.stream_id);
}
@ -1360,11 +1471,12 @@ static ssize_t cf_h2_proxy_send(struct Curl_cfilter *cf,
* We have unwritten state that needs us being invoked again and EAGAIN
* is the only way to ensure that. */
ctx->tunnel.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",
ctx->tunnel.stream_id, len,
nghttp2_session_get_remote_window_size(ctx->h2), rwin,
nwritten);
drain_tunnel(cf, data, &ctx->tunnel);
*err = CURLE_AGAIN;
nwritten = -1;
goto out;
@ -1377,14 +1489,20 @@ static ssize_t cf_h2_proxy_send(struct Curl_cfilter *cf,
nwritten = -1;
}
else {
CURL_TRC_CF(data, cf, "send: nothing to do in this session");
CURL_TRC_CF(data, cf, "[0] send: nothing to do in this session");
*err = CURLE_HTTP2;
nwritten = -1;
}
}
out:
CURL_TRC_CF(data, cf, "[h2sid=%d] cf_send(len=%zu) -> %zd, %d, "
if(!Curl_bufq_is_empty(&ctx->tunnel.recvbuf) &&
(nwritten >= 0 || *err == CURLE_AGAIN)) {
/* data pending and no fatal error to report. Need to trigger
* draining to avoid stalling when no socket events happen. */
drain_tunnel(cf, data, &ctx->tunnel);
}
CURL_TRC_CF(data, cf, "[%d] cf_send(len=%zu) -> %zd, %d, "
"h2 windows %d-%d (stream-conn), buffers %zu-%zu (stream-conn)",
ctx->tunnel.stream_id, len, nwritten, *err,
nghttp2_session_get_stream_remote_window_size(
@ -1443,7 +1561,7 @@ static bool cf_h2_proxy_is_alive(struct Curl_cfilter *cf,
CF_DATA_SAVE(save, cf, data);
result = (ctx && ctx->h2 && proxy_h2_connisalive(cf, data, input_pending));
CURL_TRC_CF(data, cf, "conn alive -> %d, input_pending=%d",
CURL_TRC_CF(data, cf, "[0] conn alive -> %d, input_pending=%d",
result, *input_pending);
CF_DATA_RESTORE(cf, save);
return result;

View file

@ -71,6 +71,7 @@
#include "warnless.h"
#include "conncache.h"
#include "multihandle.h"
#include "rand.h"
#include "share.h"
#include "version_win32.h"
@ -777,6 +778,10 @@ struct cf_socket_ctx {
struct curltime connected_at; /* when socket connected/got first byte */
struct curltime first_byte_at; /* when first byte was recvd */
int error; /* errno of last failure or 0 */
#ifdef DEBUGBUILD
int wblock_percent; /* percent of writes doing EAGAIN */
int wpartial_percent; /* percent of bytes written in send */
#endif
BIT(got_first_byte); /* if first byte was received */
BIT(accepted); /* socket was accepted, not connected */
BIT(active);
@ -792,6 +797,22 @@ static void cf_socket_ctx_init(struct cf_socket_ctx *ctx,
ctx->transport = transport;
Curl_sock_assign_addr(&ctx->addr, ai, transport);
Curl_bufq_init(&ctx->recvbuf, NW_RECV_CHUNK_SIZE, NW_RECV_CHUNKS);
#ifdef DEBUGBUILD
{
char *p = getenv("CURL_DBG_SOCK_WBLOCK");
if(p) {
long l = strtol(p, NULL, 10);
if(l >= 0 && l <= 100)
ctx->wblock_percent = (int)l;
}
p = getenv("CURL_DBG_SOCK_WPARTIAL");
if(p) {
long l = strtol(p, NULL, 10);
if(l >= 0 && l <= 100)
ctx->wpartial_percent = (int)l;
}
}
#endif
}
struct reader_ctx {
@ -1253,11 +1274,34 @@ static ssize_t cf_socket_send(struct Curl_cfilter *cf, struct Curl_easy *data,
struct cf_socket_ctx *ctx = cf->ctx;
curl_socket_t fdsave;
ssize_t nwritten;
size_t orig_len = len;
*err = CURLE_OK;
fdsave = cf->conn->sock[cf->sockindex];
cf->conn->sock[cf->sockindex] = ctx->sock;
#ifdef DEBUGBUILD
/* simulate network blocking/partial writes */
if(ctx->wblock_percent > 0) {
unsigned char c;
Curl_rand(data, &c, 1);
if(c >= ((100-ctx->wblock_percent)*256/100)) {
CURL_TRC_CF(data, cf, "send(len=%zu) SIMULATE EWOULDBLOCK", orig_len);
*err = CURLE_AGAIN;
nwritten = -1;
cf->conn->sock[cf->sockindex] = fdsave;
return nwritten;
}
}
if(cf->cft != &Curl_cft_udp && ctx->wpartial_percent > 0 && len > 8) {
len = len * ctx->wpartial_percent / 100;
if(!len)
len = 1;
CURL_TRC_CF(data, cf, "send(len=%zu) SIMULATE partial write of %zu bytes",
orig_len, len);
}
#endif
#if defined(MSG_FASTOPEN) && !defined(TCP_FASTOPEN_CONNECT) /* Linux */
if(cf->conn->bits.tcp_fastopen) {
nwritten = sendto(ctx->sock, buf, len, MSG_FASTOPEN,
@ -1297,7 +1341,7 @@ static ssize_t cf_socket_send(struct Curl_cfilter *cf, struct Curl_easy *data,
}
CURL_TRC_CF(data, cf, "send(len=%zu) -> %d, err=%d",
len, (int)nwritten, *err);
orig_len, (int)nwritten, *err);
cf->conn->sock[cf->sockindex] = fdsave;
return nwritten;
}

View file

@ -187,6 +187,7 @@ struct stream_ctx {
int status_code; /* HTTP response status code */
uint32_t error; /* stream error code */
uint32_t local_window_size; /* the local recv window size */
bool resp_hds_complete; /* we have a complete, final response */
bool closed; /* TRUE on stream close */
bool reset; /* TRUE on stream reset */
bool close_handled; /* TRUE if stream closure is handled by libcurl */
@ -1044,6 +1045,9 @@ static CURLcode on_stream_frame(struct Curl_cfilter *cf,
if(result)
return result;
if(stream->status_code / 100 != 1) {
stream->resp_hds_complete = TRUE;
}
drain_stream(cf, data, stream);
break;
case NGHTTP2_PUSH_PROMISE:
@ -1064,7 +1068,9 @@ static CURLcode on_stream_frame(struct Curl_cfilter *cf,
break;
case NGHTTP2_RST_STREAM:
stream->closed = TRUE;
stream->reset = TRUE;
if(frame->rst_stream.error_code) {
stream->reset = TRUE;
}
stream->send_closed = TRUE;
data->req.keepon &= ~KEEP_SEND_HOLD;
drain_stream(cf, data, stream);
@ -1109,8 +1115,9 @@ static int fr_print(const nghttp2_frame *frame, char *buffer, size_t blen)
}
case NGHTTP2_RST_STREAM: {
return msnprintf(buffer, blen,
"FRAME[RST_STREAM, len=%d, flags=%d]",
(int)frame->hd.length, frame->hd.flags);
"FRAME[RST_STREAM, len=%d, flags=%d, error=%u]",
(int)frame->hd.length, frame->hd.flags,
frame->rst_stream.error_code);
}
case NGHTTP2_SETTINGS: {
if(frame->hd.flags & NGHTTP2_FLAG_ACK) {
@ -1166,7 +1173,7 @@ static int on_frame_send(nghttp2_session *session, const nghttp2_frame *frame,
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);
len = fr_print(frame, buffer, sizeof(buffer)-1);
buffer[len] = 0;
CURL_TRC_CF(data, cf, "[%d] -> %s", frame->hd.stream_id, buffer);
}
@ -1187,7 +1194,7 @@ static int on_frame_recv(nghttp2_session *session, const nghttp2_frame *frame,
if(Curl_trc_cf_is_verbose(cf, data)) {
char buffer[256];
int len;
len = fr_print(frame, buffer, (sizeof(buffer)/sizeof(buffer[0]))-1);
len = fr_print(frame, buffer, sizeof(buffer)-1);
buffer[len] = 0;
CURL_TRC_CF(data, cf, "[%d] <- %s",frame->hd.stream_id, buffer);
}
@ -1975,7 +1982,14 @@ static ssize_t cf_h2_recv(struct Curl_cfilter *cf, struct Curl_easy *data,
out:
result = h2_progress_egress(cf, data);
if(result && result != CURLE_AGAIN) {
if(result == CURLE_AGAIN) {
/* pending data to send, need to be called again. Ideally, we'd
* monitor the socket for POLLOUT, but we might not be in SENDING
* transfer state any longer and are unable to make this happen.
*/
drain_stream(cf, data, stream);
}
else if(result) {
*err = result;
nread = -1;
}
@ -2151,27 +2165,17 @@ static ssize_t cf_h2_send(struct Curl_cfilter *cf, struct Curl_easy *data,
int rv;
ssize_t nwritten;
CURLcode result;
int blocked = 0;
int blocked = 0, was_blocked = 0;
CF_DATA_SAVE(save, cf, data);
if(stream && stream->id != -1) {
if(stream->close_handled) {
infof(data, "stream %u closed", stream->id);
*err = CURLE_HTTP2_STREAM;
nwritten = -1;
goto out;
}
else if(stream->closed) {
nwritten = http2_handle_stream_close(cf, data, stream, err);
goto out;
}
else if(stream->upload_blocked_len) {
if(stream->upload_blocked_len) {
/* the data in `buf` has already been submitted or added to the
* buffers, but have been EAGAINed on the last invocation. */
/* TODO: this assertion triggers in OSSFuzz runs and it is not
* clear why. Disable for now to let OSSFuzz continue its tests.
DEBUGASSERT(len >= stream->upload_blocked_len); */
* clear why. Disable for now to let OSSFuzz continue its tests. */
DEBUGASSERT(len >= stream->upload_blocked_len);
if(len < stream->upload_blocked_len) {
/* Did we get called again with a smaller `len`? This should not
* happen. We are not prepared to handle that. */
@ -2182,6 +2186,25 @@ static ssize_t cf_h2_send(struct Curl_cfilter *cf, struct Curl_easy *data,
}
nwritten = (ssize_t)stream->upload_blocked_len;
stream->upload_blocked_len = 0;
was_blocked = 1;
}
else if(stream->closed) {
if(stream->resp_hds_complete) {
/* Server decided to close the stream after having sent us a findl
* response. This is valid if it is not interested in the request
* body. This happens on 30x or 40x responses.
* We silently discard the data sent, since this is not a transport
* error situation. */
CURL_TRC_CF(data, cf, "[%d] discarding data"
"on closed stream with response", stream->id);
*err = CURLE_OK;
nwritten = (ssize_t)len;
goto out;
}
infof(data, "stream %u closed", stream->id);
*err = CURLE_SEND_ERROR;
nwritten = -1;
goto out;
}
else {
/* If stream_id != -1, we have dispatched request HEADERS and
@ -2218,8 +2241,10 @@ static ssize_t cf_h2_send(struct Curl_cfilter *cf, struct Curl_easy *data,
result = h2_progress_egress(cf, data);
/* if the stream has been closed in egress handling (nghttp2 does that
* when it does not like the headers, for example */
if(stream && stream->closed) {
nwritten = http2_handle_stream_close(cf, data, stream, err);
if(stream && stream->closed && !was_blocked) {
infof(data, "stream %u closed", stream->id);
*err = CURLE_SEND_ERROR;
nwritten = -1;
goto out;
}
else if(result == CURLE_AGAIN) {
@ -2367,8 +2392,12 @@ static CURLcode cf_h2_connect(struct Curl_cfilter *cf,
if(result)
goto out;
/* Send out our SETTINGS and ACKs and such. If that blocks, we
* have it buffered and can count this filter as being connected */
result = h2_progress_egress(cf, data);
if(result)
if(result == CURLE_AGAIN)
result = CURLE_OK;
else if(result)
goto out;
*done = TRUE;
@ -2376,6 +2405,7 @@ static CURLcode cf_h2_connect(struct Curl_cfilter *cf,
result = CURLE_OK;
out:
CURL_TRC_CF(data, cf, "cf_connect() -> %d, %d, ", result, *done);
CF_DATA_RESTORE(cf, save);
return result;
}

View file

@ -667,8 +667,14 @@ static CURLcode multi_done(struct Curl_easy *data,
struct connectdata *conn = data->conn;
unsigned int i;
#if defined(DEBUGBUILD) && !defined(CURL_DISABLE_VERBOSE_STRINGS)
DEBUGF(infof(data, "multi_done[%s]: status: %d prem: %d done: %d",
multi_statename[data->mstate],
(int)status, (int)premature, data->state.done));
#else
DEBUGF(infof(data, "multi_done: status: %d prem: %d done: %d",
(int)status, (int)premature, data->state.done));
#endif
if(data->state.done)
/* Stop if multi_done() has already been called */

View file

@ -431,6 +431,7 @@ static CURLcode readwrite_data(struct Curl_easy *data,
curl_off_t max_recv = data->set.max_recv_speed?
data->set.max_recv_speed : CURL_OFF_T_MAX;
char *buf = data->state.buffer;
bool data_eof_handled = FALSE;
DEBUGASSERT(buf);
*done = FALSE;
@ -448,8 +449,7 @@ static CURLcode readwrite_data(struct Curl_easy *data,
to ensure that http2_handle_stream_close is called when we read all
incoming bytes for a particular stream. */
bool is_http3 = Curl_conn_is_http3(data, conn, FIRSTSOCKET);
bool data_eof_handled = is_http3
|| Curl_conn_is_http2(data, conn, FIRSTSOCKET);
data_eof_handled = is_http3 || Curl_conn_is_http2(data, conn, FIRSTSOCKET);
if(!data_eof_handled && k->size != -1 && !k->header) {
/* make sure we don't read too much */
@ -761,7 +761,7 @@ static CURLcode readwrite_data(struct Curl_easy *data,
}
if(((k->keepon & (KEEP_RECV|KEEP_SEND)) == KEEP_SEND) &&
conn->bits.close) {
(conn->bits.close || data_eof_handled)) {
/* When we've read the entire thing and the close bit is set, the server
may now close the connection. If there's now any kind of sending going
on from our side, we need to stop that immediately. */

View file

@ -1106,6 +1106,7 @@ static int cb_h3_stream_close(nghttp3_conn *conn, int64_t stream_id,
else {
CURL_TRC_CF(data, cf, "[%" PRId64 "] CLOSED", stream->id);
}
data->req.keepon &= ~KEEP_SEND_HOLD;
h3_drain_stream(cf, data);
return 0;
}
@ -1785,6 +1786,18 @@ static ssize_t cf_ngtcp2_send(struct Curl_cfilter *cf, struct Curl_easy *data,
stream->upload_blocked_len = 0;
}
else if(stream->closed) {
if(stream->resp_hds_complete) {
/* Server decided to close the stream after having sent us a final
* response. This is valid if it is not interested in the request
* body. This happens on 30x or 40x responses.
* We silently discard the data sent, since this is not a transport
* error situation. */
CURL_TRC_CF(data, cf, "[%" PRId64 "] discarding data"
"on closed stream with response", stream->id);
*err = CURLE_OK;
sent = (ssize_t)len;
goto out;
}
*err = CURLE_HTTP3;
sent = -1;
goto out;
@ -2245,9 +2258,16 @@ static CURLcode cf_ngtcp2_data_event(struct Curl_cfilter *cf,
}
break;
}
case CF_CTRL_DATA_IDLE:
result = check_and_set_expiry(cf, data, NULL);
case CF_CTRL_DATA_IDLE: {
struct h3_stream_ctx *stream = H3_STREAM_CTX(data);
CURL_TRC_CF(data, cf, "data idle");
if(stream && !stream->closed) {
result = check_and_set_expiry(cf, data, NULL);
if(result)
CURL_TRC_CF(data, cf, "data idle, check_and_set_expiry -> %d", result);
}
break;
}
default:
break;
}

View file

@ -565,6 +565,7 @@ static CURLcode h3_process_event(struct Curl_cfilter *cf,
}
stream->closed = TRUE;
streamclose(cf->conn, "End of stream");
data->req.keepon &= ~KEEP_SEND_HOLD;
break;
case QUICHE_H3_EVENT_GOAWAY:
@ -1082,6 +1083,22 @@ static ssize_t cf_quiche_send(struct Curl_cfilter *cf, struct Curl_easy *data,
nwritten = -1;
goto out;
}
else if(nwritten == QUICHE_H3_TRANSPORT_ERR_INVALID_STREAM_STATE &&
stream->closed && stream->resp_hds_complete) {
/* sending request body on a stream that has been closed by the
* server. If the server has send us a final response, we should
* silently discard the send data.
* This happens for example on redirects where the server, instead
* of reading the full request body just closed the stream after
* sending the 30x response.
* This is sort of a race: had the transfer loop called recv first,
* it would see the response and stop/discard sending on its own- */
CURL_TRC_CF(data, cf, "[%" PRId64 "] discarding data"
"on closed stream with response", stream->id);
*err = CURLE_OK;
nwritten = (ssize_t)len;
goto out;
}
else if(nwritten == QUICHE_H3_TRANSPORT_ERR_FINAL_SIZE) {
CURL_TRC_CF(data, cf, "[%" PRId64 "] send_body(len=%zu) "
"-> exceeds size", stream->id, len);
@ -1213,11 +1230,15 @@ static CURLcode cf_quiche_data_event(struct Curl_cfilter *cf,
}
break;
}
case CF_CTRL_DATA_IDLE:
result = cf_flush_egress(cf, data);
if(result)
CURL_TRC_CF(data, cf, "data idle, flush egress -> %d", result);
case CF_CTRL_DATA_IDLE: {
struct stream_ctx *stream = H3_STREAM_CTX(data);
if(stream && !stream->closed) {
result = cf_flush_egress(cf, data);
if(result)
CURL_TRC_CF(data, cf, "data idle, flush egress -> %d", result);
}
break;
}
default:
break;
}

View file

@ -47,6 +47,7 @@
#include "curl_msh3.h"
#include "curl_ngtcp2.h"
#include "curl_quiche.h"
#include "rand.h"
#include "vquic.h"
#include "vquic_int.h"
#include "strerror.h"
@ -89,6 +90,16 @@ CURLcode vquic_ctx_init(struct cf_quic_ctx *qctx)
#else
qctx->no_gso = TRUE;
#endif
#ifdef DEBUGBUILD
{
char *p = getenv("CURL_DBG_QUIC_WBLOCK");
if(p) {
long l = strtol(p, NULL, 10);
if(l >= 0 && l <= 100)
qctx->wblock_percent = (int)l;
}
}
#endif
return CURLE_OK;
}
@ -231,6 +242,17 @@ static CURLcode vquic_send_packets(struct Curl_cfilter *cf,
const uint8_t *pkt, size_t pktlen,
size_t gsolen, size_t *psent)
{
#ifdef DEBUGBUILD
/* simulate network blocking/partial writes */
if(qctx->wblock_percent > 0) {
unsigned char c;
Curl_rand(data, &c, 1);
if(c >= ((100-qctx->wblock_percent)*256/100)) {
CURL_TRC_CF(data, cf, "vquic_flush() simulate EWOULDBLOCK");
return CURLE_AGAIN;
}
}
#endif
if(qctx->no_gso && pktlen > gsolen) {
return send_packet_no_gso(cf, data, qctx, pkt, pktlen, gsolen, psent);
}

View file

@ -41,6 +41,9 @@ struct cf_quic_ctx {
size_t gsolen; /* length of individual packets in send buf */
size_t split_len; /* if != 0, buffer length after which GSO differs */
size_t split_gsolen; /* length of individual packets after split_len */
#ifdef DEBUGBUILD
int wblock_percent; /* percent of writes doing EAGAIN */
#endif
bool no_gso; /* do not use gso on sending */
};

View file

@ -295,7 +295,7 @@ static int bio_cf_out_write(WOLFSSL_BIO *bio, const char *buf, int blen)
blen, nwritten, result);
wolfSSL_BIO_clear_retry_flags(bio);
if(nwritten < 0 && CURLE_AGAIN == result)
BIO_set_retry_read(bio);
BIO_set_retry_write(bio);
return (int)nwritten;
}