luo980/curl
1
0
Fork 0
Code Issues Pull Requests Actions Packages Projects Releases Wiki Activity

trace: make tracing available in non-debug builds

Browse Source 
Add --trace-config to curl

Add curl_global_trace() to libcurl

Closes #11421
This commit is contained in:
Stefan Eissing 2023-08-03 17:32:25 +02:00 committed by Daniel Stenberg
parent 0f49b5bacb
commit e12b39e133
No known key found for this signature in database
GPG Key ID: 5CC908FDB71E12C2
46 changed files with 1166 additions and 790 deletions
Show Stats Download Patch File Download Diff File Expand all files Collapse all files

1
docs/cmdline-opts/Makefile.inc
View File

@ -265,6 +265,7 @@ DPAGES = \
tlsv1.d \ tlsv1.d \
tr-encoding.d \ tr-encoding.d \
trace-ascii.d \ trace-ascii.d \
trace-config.d \
trace-ids.d \ trace-ids.d \
trace-time.d \ trace-time.d \
trace.d \ trace.d \

21
docs/cmdline-opts/trace-config.d Normal file
View File

@ -0,0 +1,21 @@
c: Copyright (C) Daniel Stenberg, <daniel@haxx.se>, et al.
SPDX-License-Identifier: curl
Long: trace-config
Arg: <string>
Help: enable
Mutexed: trace verbose
Category: verbose
Example: --trace-config ids,http/2 $URL
Added: 8.3.0
See-also: verbose trace
Multi: append
Scope: global
---
Set configuration for trace output. A comma-separated list of components
where detailed output will be made available from. Names are case-insensitive.
Specify 'all' to enable all trace components.
In addition to trace component names, specify "ids" and "time" to
avoid extra --trace-ids or --trace-time parameters.
See the *curl_global_trace(3)* man page for more details.

2
docs/cmdline-opts/trace.d
View File

@ -7,7 +7,7 @@ Mutexed: verbose trace-ascii
Category: verbose Category: verbose
Example: --trace log.txt $URL Example: --trace log.txt $URL
Added: 7.9.7 Added: 7.9.7
See-also: trace-ascii trace-ids trace-time See-also: trace-ascii trace-config trace-ids trace-time
Multi: single Multi: single
Scope: global Scope: global
--- ---

1
docs/libcurl/Makefile.inc
View File

@ -54,6 +54,7 @@ man_MANS = \
curl_global_cleanup.3 \ curl_global_cleanup.3 \
curl_global_init.3 \ curl_global_init.3 \
curl_global_init_mem.3 \ curl_global_init_mem.3 \
curl_global_trace.3 \
curl_global_sslset.3 \ curl_global_sslset.3 \
curl_mime_addpart.3 \ curl_mime_addpart.3 \
curl_mime_data.3 \ curl_mime_data.3 \

118
docs/libcurl/curl_global_trace.3 Normal file
View File

@ -0,0 +1,118 @@
.\" **************************************************************************
.\" * _ _ ____ _
.\" * Project ___| | | | _ \| |
.\" * / __| | | | |_) | |
.\" * | (__| |_| | _ <| |___
.\" * \___|\___/|_| \_\_____|
.\" *
.\" * Copyright (C) Daniel Stenberg, <daniel@haxx.se>, et al.
.\" *
.\" * This software is licensed as described in the file COPYING, which
.\" * you should have received as part of this distribution. The terms
.\" * are also available at https://curl.se/docs/copyright.html.
.\" *
.\" * You may opt to use, copy, modify, merge, publish, distribute and/or sell
.\" * copies of the Software, and permit persons to whom the Software is
.\" * furnished to do so, under the terms of the COPYING file.
.\" *
.\" * This software is distributed on an "AS IS" basis, WITHOUT WARRANTY OF ANY
.\" * KIND, either express or implied.
.\" *
.\" * SPDX-License-Identifier: curl
.\" *
.\" **************************************************************************
.TH curl_global_trace 3 "01 August 2023" "libcurl" "libcurl"
.SH NAME
curl_global_trace - Global libcurl logging configuration
.SH SYNOPSIS
.nf
#include <curl/curl.h>
CURLcode curl_global_trace(const char *config);
.fi
.SH DESCRIPTION
This function configures the logging behavior, allowing to make some
parts of curl more verbose or silent than others.
This function may be called during the initialization phase of a program. It
does not have to be. It can be called several times even, possibly overwriting
settings of previous calls.
Calling this function after transfers have been started is undefined. On
some platforms/architectures it might take effect, on others not.
This function is thread-safe since libcurl 8.3.0 if
\fIcurl_version_info(3)\fP has the CURL_VERSION_THREADSAFE feature bit set
(most platforms).
If this is not thread-safe, you must not call this function when any other
thread in the program (i.e. a thread sharing the same memory) is running.
This does not just mean no other thread that is using libcurl. Because
\fIcurl_global_init(3)\fP may call functions of other libraries that are
similarly thread unsafe, it could conflict with any other thread that uses
these other libraries.
If you are initializing libcurl from a Windows DLL you should not initialize
it from \fIDllMain\fP or a static initializer because Windows holds the loader
lock during that time and it could cause a deadlock.
The \fIconfig\fP string is a list of comma-separated component names. Names
are case-insensitive and unknown names are ignored. The special name "all"
applies to all components. Names may be prefixed with '+' or '-' to enable
or disable detailed logging for a component.
The list of component names is not part of curl's public API. Names may
be added or disappear in future versions of libcurl. Since unknown names
are silently ignored, outdated log configurations will not error when
upgrading libcurl. Given that, some names can be expected to be fairly
stable and are listed below for easy reference.
Note that log configuration applies only to transfers where debug logging
is enabled. See \fICURLOPT_VERBOSE(3)\fP or \fICURLOPT_DEBUGFUNCTION(3)\fP
on how to control that.
.SH TRACE COMPONENTS
.IP tcp
Tracing of TCP socket handling: connect, reads, writes.
.IP ssl
Tracing of SSL/TLS operations, whichever SSL backend is used in your build.
.IP http/2
Details about HTTP/2 handling: frames, events, I/O, etc.
.IP http/3
Details about HTTP/3 handling: connect, frames, events, I/O etc.
.IP http-proxy
Involved when transfers are tunneled through a HTTP proxy. "h1-proxy" or
"h2-proxy" are also involved, depending on the HTTP version negotiated with
the proxy.
In order to find out all components involved in
a transfer, run it with "all" configured. You will then see all names
involved in your libcurl version in the trace.
.SH EXAMPLE
.nf
/* log details of HTTP/2 and SSL handling */
curl_global_trace("http/2,ssl");
/* log all details, except SSL handling */
curl_global_trace("all,-ssl");
.fi
Below is a trace sample where "http/2" was configured. The trace output
of an enabled component appears at the beginning in brackets.
.nf
* [HTTP/2] [h2sid=1] cf_send(len=96) submit https://example.com/
...
* [HTTP/2] [h2sid=1] FRAME[HEADERS]
* [HTTP/2] [h2sid=1] 249 header bytes
...
.fi
.SH AVAILABILITY
Added in 8.3
.SH RETURN VALUE
If this function returns non-zero, something went wrong and the configuration
may not have any effects or may only been applied partially.
.SH "SEE ALSO"
.BR curl_global_init "(3), "
.BR libcurl "(3) "

1
docs/options-in-versions
View File

@ -252,6 +252,7 @@
--tr-encoding 7.21.6 --tr-encoding 7.21.6
--trace 7.9.7 --trace 7.9.7
--trace-ascii 7.9.7 --trace-ascii 7.9.7
--trace-config 8.3.0
--trace-ids 8.2.0 --trace-ids 8.2.0
--trace-time 7.14.0 --trace-time 7.14.0
--unix-socket 7.40.0 --unix-socket 7.40.0

14
include/curl/curl.h
View File

@ -2731,6 +2731,20 @@ CURL_EXTERN CURLcode curl_global_init_mem(long flags,
*/ */
CURL_EXTERN void curl_global_cleanup(void); CURL_EXTERN void curl_global_cleanup(void);
/*
* NAME curl_global_trace()
*
* DESCRIPTION
*
* curl_global_trace() can be invoked at application start to
* configure which components in curl should participate in tracing.
* This function is thread-safe if CURL_VERSION_THREADSAFE is set in the
* curl_version_info_data.features flag (fetch by curl_version_info()).
*/
CURL_EXTERN CURLcode curl_global_trace(const char *config);
/* linked-list structure for the CURLOPT_QUOTE option (and other) */ /* linked-list structure for the CURLOPT_QUOTE option (and other) */
struct curl_slist { struct curl_slist {
char *data; char *data;

4
lib/Makefile.inc
View File

@ -124,7 +124,6 @@ LIB_CFILES = \
curl_get_line.c \ curl_get_line.c \
curl_gethostname.c \ curl_gethostname.c \
curl_gssapi.c \ curl_gssapi.c \
curl_log.c \
curl_memrchr.c \ curl_memrchr.c \
curl_multibyte.c \ curl_multibyte.c \
curl_ntlm_core.c \ curl_ntlm_core.c \
@ -135,6 +134,7 @@ LIB_CFILES = \
curl_sasl.c \ curl_sasl.c \
curl_sspi.c \ curl_sspi.c \
curl_threads.c \ curl_threads.c \
curl_trc.c \
dict.c \ dict.c \
doh.c \ doh.c \
dynbuf.c \ dynbuf.c \
@ -260,7 +260,6 @@ LIB_HFILES = \
curl_hmac.h \ curl_hmac.h \
curl_krb5.h \ curl_krb5.h \
curl_ldap.h \ curl_ldap.h \
curl_log.h \
curl_md4.h \ curl_md4.h \
curl_md5.h \ curl_md5.h \
curl_memory.h \ curl_memory.h \
@ -278,6 +277,7 @@ LIB_HFILES = \
curl_sha256.h \ curl_sha256.h \
curl_sspi.h \ curl_sspi.h \
curl_threads.h \ curl_threads.h \
curl_trc.h \
curlx.h \ curlx.h \
dict.h \ dict.h \
doh.h \ doh.h \

34
lib/cf-h1-proxy.c
View File

@ -41,7 +41,7 @@
#include "cfilters.h" #include "cfilters.h"
#include "cf-h1-proxy.h" #include "cf-h1-proxy.h"
#include "connect.h" #include "connect.h"
#include "curl_log.h" #include "curl_trc.h"
#include "curlx.h" #include "curlx.h"
#include "vtls/vtls.h" #include "vtls/vtls.h"
#include "transfer.h" #include "transfer.h"
@ -175,36 +175,36 @@ static void h1_tunnel_go_state(struct Curl_cfilter *cf,
/* entering this one */ /* entering this one */
switch(new_state) { switch(new_state) {
case H1_TUNNEL_INIT: case H1_TUNNEL_INIT:
DEBUGF(LOG_CF(data, cf, "new tunnel state 'init'")); CURL_TRC_CF(data, cf, "new tunnel state 'init'");
tunnel_reinit(ts, cf->conn, data); tunnel_reinit(ts, cf->conn, data);
break; break;
case H1_TUNNEL_CONNECT: case H1_TUNNEL_CONNECT:
DEBUGF(LOG_CF(data, cf, "new tunnel state 'connect'")); CURL_TRC_CF(data, cf, "new tunnel state 'connect'");
ts->tunnel_state = H1_TUNNEL_CONNECT; ts->tunnel_state = H1_TUNNEL_CONNECT;
ts->keepon = KEEPON_CONNECT; ts->keepon = KEEPON_CONNECT;
Curl_dyn_reset(&ts->rcvbuf); Curl_dyn_reset(&ts->rcvbuf);
break; break;
case H1_TUNNEL_RECEIVE: case H1_TUNNEL_RECEIVE:
DEBUGF(LOG_CF(data, cf, "new tunnel state 'receive'")); CURL_TRC_CF(data, cf, "new tunnel state 'receive'");
ts->tunnel_state = H1_TUNNEL_RECEIVE; ts->tunnel_state = H1_TUNNEL_RECEIVE;
break; break;
case H1_TUNNEL_RESPONSE: case H1_TUNNEL_RESPONSE:
DEBUGF(LOG_CF(data, cf, "new tunnel state 'response'")); CURL_TRC_CF(data, cf, "new tunnel state 'response'");
ts->tunnel_state = H1_TUNNEL_RESPONSE; ts->tunnel_state = H1_TUNNEL_RESPONSE;
break; break;
case H1_TUNNEL_ESTABLISHED: case H1_TUNNEL_ESTABLISHED:
DEBUGF(LOG_CF(data, cf, "new tunnel state 'established'")); CURL_TRC_CF(data, cf, "new tunnel state 'established'");
infof(data, "CONNECT phase completed"); infof(data, "CONNECT phase completed");
data->state.authproxy.done = TRUE; data->state.authproxy.done = TRUE;
data->state.authproxy.multipass = FALSE; data->state.authproxy.multipass = FALSE;
/* FALLTHROUGH */ /* FALLTHROUGH */
case H1_TUNNEL_FAILED: case H1_TUNNEL_FAILED:
if(new_state == H1_TUNNEL_FAILED) if(new_state == H1_TUNNEL_FAILED)
DEBUGF(LOG_CF(data, cf, "new tunnel state 'failed'")); CURL_TRC_CF(data, cf, "new tunnel state 'failed'");
ts->tunnel_state = new_state; ts->tunnel_state = new_state;
Curl_dyn_reset(&ts->rcvbuf); Curl_dyn_reset(&ts->rcvbuf);
Curl_dyn_reset(&ts->req); Curl_dyn_reset(&ts->req);
@ -416,7 +416,7 @@ static CURLcode on_resp_header(struct Curl_cfilter *cf,
if(!auth) if(!auth)
return CURLE_OUT_OF_MEMORY; return CURLE_OUT_OF_MEMORY;
DEBUGF(LOG_CF(data, cf, "CONNECT: fwd auth header '%s'", header)); CURL_TRC_CF(data, cf, "CONNECT: fwd auth header '%s'", header);
result = Curl_http_input_auth(data, proxy, auth); result = Curl_http_input_auth(data, proxy, auth);
free(auth); free(auth);
@ -638,7 +638,7 @@ static CURLcode recv_CONNECT_resp(struct Curl_cfilter *cf,
/* without content-length or chunked encoding, we /* without content-length or chunked encoding, we
can't keep the connection alive since the close is can't keep the connection alive since the close is
the end signal so we bail out at once instead */ the end signal so we bail out at once instead */
DEBUGF(LOG_CF(data, cf, "CONNECT: no content-length or chunked")); CURL_TRC_CF(data, cf, "CONNECT: no content-length or chunked");
ts->keepon = KEEPON_DONE; ts->keepon = KEEPON_DONE;
} }
} }
@ -977,7 +977,7 @@ static CURLcode H1_CONNECT(struct Curl_cfilter *cf,
switch(ts->tunnel_state) { switch(ts->tunnel_state) {
case H1_TUNNEL_INIT: case H1_TUNNEL_INIT:
/* Prepare the CONNECT request and make a first attempt to send. */ /* Prepare the CONNECT request and make a first attempt to send. */
DEBUGF(LOG_CF(data, cf, "CONNECT start")); CURL_TRC_CF(data, cf, "CONNECT start");
result = start_CONNECT(cf, data, ts); result = start_CONNECT(cf, data, ts);
if(result) if(result)
goto out; goto out;
@ -986,7 +986,7 @@ static CURLcode H1_CONNECT(struct Curl_cfilter *cf,
case H1_TUNNEL_CONNECT: case H1_TUNNEL_CONNECT:
/* see that the request is completely sent */ /* see that the request is completely sent */
DEBUGF(LOG_CF(data, cf, "CONNECT send")); CURL_TRC_CF(data, cf, "CONNECT send");
result = send_CONNECT(data, cf->conn, ts, &done); result = send_CONNECT(data, cf->conn, ts, &done);
if(result || !done) if(result || !done)
goto out; goto out;
@ -995,7 +995,7 @@ static CURLcode H1_CONNECT(struct Curl_cfilter *cf,
case H1_TUNNEL_RECEIVE: case H1_TUNNEL_RECEIVE:
/* read what is there */ /* read what is there */
DEBUGF(LOG_CF(data, cf, "CONNECT receive")); CURL_TRC_CF(data, cf, "CONNECT receive");
result = recv_CONNECT_resp(cf, data, ts, &done); result = recv_CONNECT_resp(cf, data, ts, &done);
if(Curl_pgrsUpdate(data)) { if(Curl_pgrsUpdate(data)) {
result = CURLE_ABORTED_BY_CALLBACK; result = CURLE_ABORTED_BY_CALLBACK;
@ -1009,7 +1009,7 @@ static CURLcode H1_CONNECT(struct Curl_cfilter *cf,
/* FALLTHROUGH */ /* FALLTHROUGH */
case H1_TUNNEL_RESPONSE: case H1_TUNNEL_RESPONSE:
DEBUGF(LOG_CF(data, cf, "CONNECT response")); CURL_TRC_CF(data, cf, "CONNECT response");
if(data->req.newurl) { if(data->req.newurl) {
/* not the "final" response, we need to do a follow up request. /* not the "final" response, we need to do a follow up request.
* If the other side indicated a connection close, or if someone * If the other side indicated a connection close, or if someone
@ -1021,7 +1021,7 @@ static CURLcode H1_CONNECT(struct Curl_cfilter *cf,
* reset our tunnel state. To avoid recursion, we return * reset our tunnel state. To avoid recursion, we return
* and expect to be called again. * and expect to be called again.
*/ */
DEBUGF(LOG_CF(data, cf, "CONNECT need to close+open")); CURL_TRC_CF(data, cf, "CONNECT need to close+open");
infof(data, "Connect me again please"); infof(data, "Connect me again please");
Curl_conn_cf_close(cf, data); Curl_conn_cf_close(cf, data);
connkeep(conn, "HTTP proxy CONNECT"); connkeep(conn, "HTTP proxy CONNECT");
@ -1075,7 +1075,7 @@ static CURLcode cf_h1_proxy_connect(struct Curl_cfilter *cf,
return CURLE_OK; return CURLE_OK;
} }
DEBUGF(LOG_CF(data, cf, "connect")); CURL_TRC_CF(data, cf, "connect");
result = cf->next->cft->do_connect(cf->next, data, blocking, done); result = cf->next->cft->do_connect(cf->next, data, blocking, done);
if(result || !*done) if(result || !*done)
return result; return result;
@ -1135,14 +1135,14 @@ static int cf_h1_proxy_get_select_socks(struct Curl_cfilter *cf,
static void cf_h1_proxy_destroy(struct Curl_cfilter *cf, static void cf_h1_proxy_destroy(struct Curl_cfilter *cf,
struct Curl_easy *data) struct Curl_easy *data)
{ {
DEBUGF(LOG_CF(data, cf, "destroy")); CURL_TRC_CF(data, cf, "destroy");
tunnel_free(cf, data); tunnel_free(cf, data);
} }
static void cf_h1_proxy_close(struct Curl_cfilter *cf, static void cf_h1_proxy_close(struct Curl_cfilter *cf,
struct Curl_easy *data) struct Curl_easy *data)
{ {
DEBUGF(LOG_CF(data, cf, "close")); CURL_TRC_CF(data, cf, "close");
cf->connected = FALSE; cf->connected = FALSE;
if(cf->ctx) { if(cf->ctx) {
h1_tunnel_go_state(cf, cf->ctx, H1_TUNNEL_INIT, data); h1_tunnel_go_state(cf, cf->ctx, H1_TUNNEL_INIT, data);

156
lib/cf-h2-proxy.c
View File

@ -30,7 +30,7 @@
#include "urldata.h" #include "urldata.h"
#include "cfilters.h" #include "cfilters.h"
#include "connect.h" #include "connect.h"
#include "curl_log.h" #include "curl_trc.h"
#include "bufq.h" #include "bufq.h"
#include "dynbuf.h" #include "dynbuf.h"
#include "dynhds.h" #include "dynhds.h"
@ -146,29 +146,29 @@ static void h2_tunnel_go_state(struct Curl_cfilter *cf,
/* entering this one */ /* entering this one */
switch(new_state) { switch(new_state) {
case H2_TUNNEL_INIT: case H2_TUNNEL_INIT:
DEBUGF(LOG_CF(data, cf, "new tunnel state 'init'")); CURL_TRC_CF(data, cf, "new tunnel state 'init'");
tunnel_stream_clear(ts); tunnel_stream_clear(ts);
break; break;
case H2_TUNNEL_CONNECT: case H2_TUNNEL_CONNECT:
DEBUGF(LOG_CF(data, cf, "new tunnel state 'connect'")); CURL_TRC_CF(data, cf, "new tunnel state 'connect'");
ts->state = H2_TUNNEL_CONNECT; ts->state = H2_TUNNEL_CONNECT;
break; break;
case H2_TUNNEL_RESPONSE: case H2_TUNNEL_RESPONSE:
DEBUGF(LOG_CF(data, cf, "new tunnel state 'response'")); CURL_TRC_CF(data, cf, "new tunnel state 'response'");
ts->state = H2_TUNNEL_RESPONSE; ts->state = H2_TUNNEL_RESPONSE;
break; break;
case H2_TUNNEL_ESTABLISHED: case H2_TUNNEL_ESTABLISHED:
DEBUGF(LOG_CF(data, cf, "new tunnel state 'established'")); CURL_TRC_CF(data, cf, "new tunnel state 'established'");
infof(data, "CONNECT phase completed"); infof(data, "CONNECT phase completed");
data->state.authproxy.done = TRUE; data->state.authproxy.done = TRUE;
data->state.authproxy.multipass = FALSE; data->state.authproxy.multipass = FALSE;
/* FALLTHROUGH */ /* FALLTHROUGH */
case H2_TUNNEL_FAILED: case H2_TUNNEL_FAILED:
if(new_state == H2_TUNNEL_FAILED) if(new_state == H2_TUNNEL_FAILED)
DEBUGF(LOG_CF(data, cf, "new tunnel state 'failed'")); CURL_TRC_CF(data, cf, "new tunnel state 'failed'");
ts->state = new_state; ts->state = new_state;
/* If a proxy-authorization header was used for the proxy, then we should /* 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 make sure that it isn't accidentally used for the document request
@ -232,8 +232,8 @@ static void drain_tunnel(struct Curl_cfilter *cf,
if(!tunnel->closed && !tunnel->reset && tunnel->upload_blocked_len) if(!tunnel->closed && !tunnel->reset && tunnel->upload_blocked_len)
bits |= CURL_CSELECT_OUT; bits |= CURL_CSELECT_OUT;
if(data->state.dselect_bits != bits) { if(data->state.dselect_bits != bits) {
DEBUGF(LOG_CF(data, cf, "[h2sid=%d] DRAIN dselect_bits=%x", CURL_TRC_CF(data, cf, "[h2sid=%d] DRAIN dselect_bits=%x",
tunnel->stream_id, bits)); tunnel->stream_id, bits);
data->state.dselect_bits = bits; data->state.dselect_bits = bits;
Curl_expire(data, 0, EXPIRE_RUN_NOW); Curl_expire(data, 0, EXPIRE_RUN_NOW);
} }
@ -248,8 +248,8 @@ static ssize_t proxy_nw_in_reader(void *reader_ctx,
ssize_t nread; ssize_t nread;
nread = Curl_conn_cf_recv(cf->next, data, (char *)buf, buflen, err); nread = Curl_conn_cf_recv(cf->next, data, (char *)buf, buflen, err);
DEBUGF(LOG_CF(data, cf, "nw_in_reader(len=%zu) -> %zd, %d", CURL_TRC_CF(data, cf, "nw_in_reader(len=%zu) -> %zd, %d",
buflen, nread, *err)); buflen, nread, *err);
return nread; return nread;
} }
@ -262,8 +262,8 @@ static ssize_t proxy_h2_nw_out_writer(void *writer_ctx,
ssize_t nwritten; ssize_t nwritten;
nwritten = 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);
DEBUGF(LOG_CF(data, cf, "nw_out_writer(len=%zu) -> %zd, %d", CURL_TRC_CF(data, cf, "nw_out_writer(len=%zu) -> %zd, %d",
buflen, nwritten, *err)); buflen, nwritten, *err);
return nwritten; return nwritten;
} }
@ -384,7 +384,7 @@ static CURLcode cf_h2_proxy_ctx_init(struct Curl_cfilter *cf,
out: out:
if(cbs) if(cbs)
nghttp2_session_callbacks_del(cbs); nghttp2_session_callbacks_del(cbs);
DEBUGF(LOG_CF(data, cf, "init proxy ctx -> %d", result)); CURL_TRC_CF(data, cf, "init proxy ctx -> %d", result);
return result; return result;
} }
@ -409,13 +409,13 @@ static CURLcode proxy_h2_nw_out_flush(struct Curl_cfilter *cf,
&result); &result);
if(nwritten < 0) { if(nwritten < 0) {
if(result == CURLE_AGAIN) { if(result == CURLE_AGAIN) {
DEBUGF(LOG_CF(data, cf, "flush nw send buffer(%zu) -> EAGAIN", CURL_TRC_CF(data, cf, "flush nw send buffer(%zu) -> EAGAIN",
Curl_bufq_len(&ctx->outbufq))); Curl_bufq_len(&ctx->outbufq));
ctx->nw_out_blocked = 1; ctx->nw_out_blocked = 1;
} }
return result; return result;
} }
DEBUGF(LOG_CF(data, cf, "nw send buffer flushed")); CURL_TRC_CF(data, cf, "nw send buffer flushed");
return Curl_bufq_is_empty(&ctx->outbufq)? CURLE_OK: CURLE_AGAIN; return Curl_bufq_is_empty(&ctx->outbufq)? CURLE_OK: CURLE_AGAIN;
} }
@ -436,8 +436,7 @@ static int proxy_h2_process_pending_input(struct Curl_cfilter *cf,
while(Curl_bufq_peek(&ctx->inbufq, &buf, &blen)) { while(Curl_bufq_peek(&ctx->inbufq, &buf, &blen)) {
rv = nghttp2_session_mem_recv(ctx->h2, (const uint8_t *)buf, blen); rv = nghttp2_session_mem_recv(ctx->h2, (const uint8_t *)buf, blen);
DEBUGF(LOG_CF(data, cf, CURL_TRC_CF(data, cf, "fed %zu bytes from nw to nghttp2 -> %zd", blen, rv);
"fed %zu bytes from nw to nghttp2 -> %zd", blen, rv));
if(rv < 0) { if(rv < 0) {
failf(data, failf(data,
"process_pending_input: nghttp2_session_mem_recv() returned " "process_pending_input: nghttp2_session_mem_recv() returned "
@ -447,12 +446,12 @@ static int proxy_h2_process_pending_input(struct Curl_cfilter *cf,
} }
Curl_bufq_skip(&ctx->inbufq, (size_t)rv); Curl_bufq_skip(&ctx->inbufq, (size_t)rv);
if(Curl_bufq_is_empty(&ctx->inbufq)) { if(Curl_bufq_is_empty(&ctx->inbufq)) {
DEBUGF(LOG_CF(data, cf, "all data in connection buffer processed")); CURL_TRC_CF(data, cf, "all data in connection buffer processed");
break; break;
} }
else { else {
DEBUGF(LOG_CF(data, cf, "process_pending_input: %zu bytes left " CURL_TRC_CF(data, cf, "process_pending_input: %zu bytes left "
"in connection buffer", Curl_bufq_len(&ctx->inbufq))); "in connection buffer", Curl_bufq_len(&ctx->inbufq));
} }
} }
@ -468,8 +467,8 @@ static CURLcode proxy_h2_progress_ingress(struct Curl_cfilter *cf,
/* Process network input buffer fist */ /* Process network input buffer fist */
if(!Curl_bufq_is_empty(&ctx->inbufq)) { if(!Curl_bufq_is_empty(&ctx->inbufq)) {
DEBUGF(LOG_CF(data, cf, "Process %zu bytes in connection buffer", CURL_TRC_CF(data, cf, "Process %zu bytes in connection buffer",
Curl_bufq_len(&ctx->inbufq))); Curl_bufq_len(&ctx->inbufq));
if(proxy_h2_process_pending_input(cf, data, &result) < 0) if(proxy_h2_process_pending_input(cf, data, &result) < 0)
return result; return result;
} }
@ -482,8 +481,8 @@ static CURLcode proxy_h2_progress_ingress(struct Curl_cfilter *cf,
!Curl_bufq_is_full(&ctx->tunnel.recvbuf)) { !Curl_bufq_is_full(&ctx->tunnel.recvbuf)) {
nread = Curl_bufq_slurp(&ctx->inbufq, proxy_nw_in_reader, cf, &result); nread = Curl_bufq_slurp(&ctx->inbufq, proxy_nw_in_reader, cf, &result);
DEBUGF(LOG_CF(data, cf, "read %zu bytes nw data -> %zd, %d", CURL_TRC_CF(data, cf, "read %zu bytes nw data -> %zd, %d",
Curl_bufq_len(&ctx->inbufq), nread, result)); Curl_bufq_len(&ctx->inbufq), nread, result);
if(nread < 0) { if(nread < 0) {
if(result != CURLE_AGAIN) { if(result != CURLE_AGAIN) {
failf(data, "Failed receiving HTTP2 data"); failf(data, "Failed receiving HTTP2 data");
@ -518,8 +517,8 @@ static CURLcode proxy_h2_progress_egress(struct Curl_cfilter *cf,
rv = nghttp2_session_send(ctx->h2); rv = nghttp2_session_send(ctx->h2);
if(nghttp2_is_fatal(rv)) { if(nghttp2_is_fatal(rv)) {
DEBUGF(LOG_CF(data, cf, "nghttp2_session_send error (%s)%d", CURL_TRC_CF(data, cf, "nghttp2_session_send error (%s)%d",
nghttp2_strerror(rv), rv)); nghttp2_strerror(rv), rv);
return CURLE_SEND_ERROR; return CURLE_SEND_ERROR;
} }
return proxy_h2_nw_out_flush(cf, data); return proxy_h2_nw_out_flush(cf, data);
@ -579,27 +578,26 @@ static int proxy_h2_on_frame_recv(nghttp2_session *session,
ctx->goaway = TRUE; ctx->goaway = TRUE;
break; break;
case NGHTTP2_WINDOW_UPDATE: case NGHTTP2_WINDOW_UPDATE:
DEBUGF(LOG_CF(data, cf, "recv frame WINDOW_UPDATE")); CURL_TRC_CF(data, cf, "recv frame WINDOW_UPDATE");
break; break;
default: default:
DEBUGF(LOG_CF(data, cf, "recv frame %x on 0", frame->hd.type)); CURL_TRC_CF(data, cf, "recv frame %x on 0", frame->hd.type);
} }
return 0; return 0;
} }
if(stream_id != ctx->tunnel.stream_id) { if(stream_id != ctx->tunnel.stream_id) {
DEBUGF(LOG_CF(data, cf, "[h2sid=%u] rcvd FRAME not for tunnel", CURL_TRC_CF(data, cf, "[h2sid=%u] rcvd FRAME not for tunnel", stream_id);
stream_id));
return NGHTTP2_ERR_CALLBACK_FAILURE; return NGHTTP2_ERR_CALLBACK_FAILURE;
} }
switch(frame->hd.type) { switch(frame->hd.type) {
case NGHTTP2_DATA: case NGHTTP2_DATA:
/* If body started on this stream, then receiving DATA is illegal. */ /* If body started on this stream, then receiving DATA is illegal. */
DEBUGF(LOG_CF(data, cf, "[h2sid=%u] recv frame DATA", stream_id)); CURL_TRC_CF(data, cf, "[h2sid=%u] recv frame DATA", stream_id);
break; break;
case NGHTTP2_HEADERS: case NGHTTP2_HEADERS:
DEBUGF(LOG_CF(data, cf, "[h2sid=%u] recv frame HEADERS", stream_id)); CURL_TRC_CF(data, cf, "[h2sid=%u] recv frame HEADERS", stream_id);
/* nghttp2 guarantees that :status is received, and we store it to /* nghttp2 guarantees that :status is received, and we store it to
stream->status_code. Fuzzing has proven this can still be reached stream->status_code. Fuzzing has proven this can still be reached
@ -607,8 +605,8 @@ static int proxy_h2_on_frame_recv(nghttp2_session *session,
if(!ctx->tunnel.resp) if(!ctx->tunnel.resp)
return NGHTTP2_ERR_CALLBACK_FAILURE; return NGHTTP2_ERR_CALLBACK_FAILURE;
/* Only final status code signals the end of header */ /* Only final status code signals the end of header */
DEBUGF(LOG_CF(data, cf, "[h2sid=%u] got http status: %d", CURL_TRC_CF(data, cf, "[h2sid=%u] got http status: %d",
stream_id, ctx->tunnel.resp->status)); stream_id, ctx->tunnel.resp->status);
if(!ctx->tunnel.has_final_response) { if(!ctx->tunnel.has_final_response) {
if(ctx->tunnel.resp->status / 100 != 1) { if(ctx->tunnel.resp->status / 100 != 1) {
ctx->tunnel.has_final_response = TRUE; ctx->tunnel.has_final_response = TRUE;
@ -616,25 +614,25 @@ static int proxy_h2_on_frame_recv(nghttp2_session *session,
} }
break; break;
case NGHTTP2_PUSH_PROMISE: case NGHTTP2_PUSH_PROMISE:
DEBUGF(LOG_CF(data, cf, "[h2sid=%u] recv PUSH_PROMISE", stream_id)); CURL_TRC_CF(data, cf, "[h2sid=%u] recv PUSH_PROMISE", stream_id);
return NGHTTP2_ERR_CALLBACK_FAILURE; return NGHTTP2_ERR_CALLBACK_FAILURE;
case NGHTTP2_RST_STREAM: case NGHTTP2_RST_STREAM:
DEBUGF(LOG_CF(data, cf, "[h2sid=%u] recv RST", stream_id)); CURL_TRC_CF(data, cf, "[h2sid=%u] recv RST", stream_id);
ctx->tunnel.reset = TRUE; ctx->tunnel.reset = TRUE;
break; break;
case NGHTTP2_WINDOW_UPDATE: case NGHTTP2_WINDOW_UPDATE:
DEBUGF(LOG_CF(data, cf, "[h2sid=%u] recv WINDOW_UPDATE", stream_id)); CURL_TRC_CF(data, cf, "[h2sid=%u] recv WINDOW_UPDATE", stream_id);
if((data->req.keepon & KEEP_SEND_HOLD) && if((data->req.keepon & KEEP_SEND_HOLD) &&
(data->req.keepon & KEEP_SEND)) { (data->req.keepon & KEEP_SEND)) {
data->req.keepon &= ~KEEP_SEND_HOLD; data->req.keepon &= ~KEEP_SEND_HOLD;
Curl_expire(data, 0, EXPIRE_RUN_NOW); Curl_expire(data, 0, EXPIRE_RUN_NOW);
DEBUGF(LOG_CF(data, cf, "[h2sid=%u] unpausing after win update", CURL_TRC_CF(data, cf, "[h2sid=%u] unpausing after win update",
stream_id)); stream_id);
} }
break; break;
default: default:
DEBUGF(LOG_CF(data, cf, "[h2sid=%u] recv frame %x", CURL_TRC_CF(data, cf, "[h2sid=%u] recv frame %x",
stream_id, frame->hd.type)); stream_id, frame->hd.type);
break; break;
} }
return 0; return 0;
@ -658,10 +656,9 @@ static int proxy_h2_on_header(nghttp2_session *session,
(void)session; (void)session;
DEBUGASSERT(stream_id); /* should never be a zero stream ID here */ DEBUGASSERT(stream_id); /* should never be a zero stream ID here */
if(stream_id != ctx->tunnel.stream_id) { if(stream_id != ctx->tunnel.stream_id) {
DEBUGF(LOG_CF(data, cf, "[h2sid=%u] header for non-tunnel stream: " CURL_TRC_CF(data, cf, "[h2sid=%u] header for non-tunnel stream: "
"%.*s: %.*s", stream_id, "%.*s: %.*s", stream_id,
(int)namelen, name, (int)namelen, name, (int)valuelen, value);
(int)valuelen, value));
return NGHTTP2_ERR_CALLBACK_FAILURE; return NGHTTP2_ERR_CALLBACK_FAILURE;
} }
@ -689,8 +686,8 @@ static int proxy_h2_on_header(nghttp2_session *session,
return NGHTTP2_ERR_CALLBACK_FAILURE; return NGHTTP2_ERR_CALLBACK_FAILURE;
resp->prev = ctx->tunnel.resp; resp->prev = ctx->tunnel.resp;
ctx->tunnel.resp = resp; ctx->tunnel.resp = resp;
DEBUGF(LOG_CF(data, cf, "[h2sid=%u] status: HTTP/2 %03d", CURL_TRC_CF(data, cf, "[h2sid=%u] status: HTTP/2 %03d",
stream_id, ctx->tunnel.resp->status)); stream_id, ctx->tunnel.resp->status);
return 0; return 0;
} }
@ -703,10 +700,8 @@ static int proxy_h2_on_header(nghttp2_session *session,
if(result) if(result)
return NGHTTP2_ERR_CALLBACK_FAILURE; return NGHTTP2_ERR_CALLBACK_FAILURE;
DEBUGF(LOG_CF(data, cf, "[h2sid=%u] header: %.*s: %.*s", CURL_TRC_CF(data, cf, "[h2sid=%u] header: %.*s: %.*s",
stream_id, stream_id, (int)namelen, name, (int)valuelen, value);
(int)namelen, name,
(int)valuelen, value));
return 0; /* 0 is successful */ return 0; /* 0 is successful */
} }
@ -746,8 +741,8 @@ static ssize_t tunnel_send_callback(nghttp2_session *session,
if(ts->closed && Curl_bufq_is_empty(&ts->sendbuf)) if(ts->closed && Curl_bufq_is_empty(&ts->sendbuf))
*data_flags = NGHTTP2_DATA_FLAG_EOF; *data_flags = NGHTTP2_DATA_FLAG_EOF;
DEBUGF(LOG_CF(data, cf, "[h2sid=%u] tunnel_send_callback -> %zd", CURL_TRC_CF(data, cf, "[h2sid=%u] tunnel_send_callback -> %zd",
ts->stream_id, nread)); ts->stream_id, nread);
return nread; return nread;
} }
@ -791,8 +786,8 @@ static int proxy_h2_on_stream_close(nghttp2_session *session,
if(stream_id != ctx->tunnel.stream_id) if(stream_id != ctx->tunnel.stream_id)
return 0; return 0;
DEBUGF(LOG_CF(data, cf, "[h2sid=%u] proxy_h2_on_stream_close, %s (err %d)", CURL_TRC_CF(data, cf, "[h2sid=%u] proxy_h2_on_stream_close, %s (err %d)",
stream_id, nghttp2_http2_strerror(error_code), error_code)); stream_id, nghttp2_http2_strerror(error_code), error_code);
ctx->tunnel.closed = TRUE; ctx->tunnel.closed = TRUE;
ctx->tunnel.error = error_code; ctx->tunnel.error = error_code;
@ -910,8 +905,8 @@ static CURLcode submit_CONNECT(struct Curl_cfilter *cf,
result = proxy_h2_submit(&ts->stream_id, cf, data, ctx->h2, req, result = proxy_h2_submit(&ts->stream_id, cf, data, ctx->h2, req,
NULL, ts, tunnel_send_callback, cf); NULL, ts, tunnel_send_callback, cf);
if(result) { if(result) {
DEBUGF(LOG_CF(data, cf, "send: nghttp2_submit_request error (%s)%u", CURL_TRC_CF(data, cf, "send: nghttp2_submit_request error (%s)%u",
nghttp2_strerror(ts->stream_id), ts->stream_id)); nghttp2_strerror(ts->stream_id), ts->stream_id);
} }
out: out:
@ -945,8 +940,8 @@ static CURLcode inspect_response(struct Curl_cfilter *cf,
} }
if(auth_reply) { if(auth_reply) {
DEBUGF(LOG_CF(data, cf, "CONNECT: fwd auth header '%s'", CURL_TRC_CF(data, cf, "CONNECT: fwd auth header '%s'",
auth_reply->value)); auth_reply->value);
result = Curl_http_input_auth(data, ts->resp->status == 407, result = Curl_http_input_auth(data, ts->resp->status == 407,
auth_reply->value); auth_reply->value);
if(result) if(result)
@ -976,7 +971,7 @@ static CURLcode H2_CONNECT(struct Curl_cfilter *cf,
switch(ts->state) { switch(ts->state) {
case H2_TUNNEL_INIT: case H2_TUNNEL_INIT:
/* Prepare the CONNECT request and make a first attempt to send. */ /* Prepare the CONNECT request and make a first attempt to send. */
DEBUGF(LOG_CF(data, cf, "CONNECT start for %s", ts->authority)); CURL_TRC_CF(data, cf, "CONNECT start for %s", ts->authority);
result = submit_CONNECT(cf, data, ts); result = submit_CONNECT(cf, data, ts);
if(result) if(result)
goto out; goto out;
@ -1143,8 +1138,8 @@ static ssize_t h2_handle_tunnel_close(struct Curl_cfilter *cf,
ssize_t rv = 0; ssize_t rv = 0;
if(ctx->tunnel.error == NGHTTP2_REFUSED_STREAM) { if(ctx->tunnel.error == NGHTTP2_REFUSED_STREAM) {
DEBUGF(LOG_CF(data, cf, "[h2sid=%u] REFUSED_STREAM, try again on a new " CURL_TRC_CF(data, cf, "[h2sid=%u] REFUSED_STREAM, try again on a new "
"connection", ctx->tunnel.stream_id)); "connection", ctx->tunnel.stream_id);
connclose(cf->conn, "REFUSED_STREAM"); /* don't use this anymore */ connclose(cf->conn, "REFUSED_STREAM"); /* don't use this anymore */
*err = CURLE_RECV_ERROR; /* trigger Curl_retry_request() later */ *err = CURLE_RECV_ERROR; /* trigger Curl_retry_request() later */
return -1; return -1;
@ -1164,7 +1159,7 @@ static ssize_t h2_handle_tunnel_close(struct Curl_cfilter *cf,
*err = CURLE_OK; *err = CURLE_OK;
rv = 0; rv = 0;
DEBUGF(LOG_CF(data, cf, "handle_tunnel_close -> %zd, %d", rv, *err)); CURL_TRC_CF(data, cf, "handle_tunnel_close -> %zd, %d", rv, *err);
return rv; return rv;
} }
@ -1200,8 +1195,8 @@ static ssize_t tunnel_recv(struct Curl_cfilter *cf, struct Curl_easy *data,
} }
out: out:
DEBUGF(LOG_CF(data, cf, "tunnel_recv(len=%zu) -> %zd, %d", CURL_TRC_CF(data, cf, "tunnel_recv(len=%zu) -> %zd, %d",
len, nread, *err)); len, nread, *err);
return nread; return nread;
} }
@ -1229,8 +1224,8 @@ static ssize_t cf_h2_proxy_recv(struct Curl_cfilter *cf,
nread = tunnel_recv(cf, data, buf, len, err); nread = tunnel_recv(cf, data, buf, len, err);
if(nread > 0) { if(nread > 0) {
DEBUGF(LOG_CF(data, cf, "[h2sid=%u] increase window by %zd", CURL_TRC_CF(data, cf, "[h2sid=%u] increase window by %zd",
ctx->tunnel.stream_id, nread)); ctx->tunnel.stream_id, nread);
nghttp2_session_consume(ctx->h2, ctx->tunnel.stream_id, (size_t)nread); nghttp2_session_consume(ctx->h2, ctx->tunnel.stream_id, (size_t)nread);
} }
@ -1247,8 +1242,8 @@ out:
* draining to avoid stalling when no socket events happen. */ * draining to avoid stalling when no socket events happen. */
drain_tunnel(cf, data, &ctx->tunnel); drain_tunnel(cf, data, &ctx->tunnel);
} }
DEBUGF(LOG_CF(data, cf, "[h2sid=%u] cf_recv(len=%zu) -> %zd %d", CURL_TRC_CF(data, cf, "[h2sid=%u] cf_recv(len=%zu) -> %zd %d",
ctx->tunnel.stream_id, len, nread, *err)); ctx->tunnel.stream_id, len, nread, *err);
CF_DATA_RESTORE(cf, save); CF_DATA_RESTORE(cf, save);
return nread; return nread;
} }
@ -1346,19 +1341,19 @@ static ssize_t cf_h2_proxy_send(struct Curl_cfilter *cf,
* proxy connection AND to UNHOLD all of them again when the * proxy connection AND to UNHOLD all of them again when the
* window increases. * window increases.
* We *could* iterate over all data on this conn maybe? */ * We *could* iterate over all data on this conn maybe? */
DEBUGF(LOG_CF(data, cf, "[h2sid=%d] remote flow " CURL_TRC_CF(data, cf, "[h2sid=%d] remote flow "
"window is exhausted", ctx->tunnel.stream_id)); "window is exhausted", ctx->tunnel.stream_id);
} }
/* Whatever the cause, we need to return CURL_EAGAIN for this call. /* Whatever the cause, we need to return CURL_EAGAIN for this call.
* We have unwritten state that needs us being invoked again and EAGAIN * We have unwritten state that needs us being invoked again and EAGAIN
* is the only way to ensure that. */ * is the only way to ensure that. */
ctx->tunnel.upload_blocked_len = nwritten; ctx->tunnel.upload_blocked_len = nwritten;
DEBUGF(LOG_CF(data, cf, "[h2sid=%d] cf_send(len=%zu) BLOCK: win %u/%zu " CURL_TRC_CF(data, cf, "[h2sid=%d] cf_send(len=%zu) BLOCK: win %u/%zu "
"blocked_len=%zu", "blocked_len=%zu",
ctx->tunnel.stream_id, len, ctx->tunnel.stream_id, len,
nghttp2_session_get_remote_window_size(ctx->h2), rwin, nghttp2_session_get_remote_window_size(ctx->h2), rwin,
nwritten)); nwritten);
*err = CURLE_AGAIN; *err = CURLE_AGAIN;
nwritten = -1; nwritten = -1;
goto out; goto out;
@ -1371,22 +1366,21 @@ static ssize_t cf_h2_proxy_send(struct Curl_cfilter *cf,
nwritten = -1; nwritten = -1;
} }
else { else {
DEBUGF(LOG_CF(data, cf, "send: nothing to do in this session")); CURL_TRC_CF(data, cf, "send: nothing to do in this session");
*err = CURLE_HTTP2; *err = CURLE_HTTP2;
nwritten = -1; nwritten = -1;
} }
} }
out: out:
DEBUGF(LOG_CF(data, cf, "[h2sid=%d] cf_send(len=%zu) -> %zd, %d, " CURL_TRC_CF(data, cf, "[h2sid=%d] cf_send(len=%zu) -> %zd, %d, "
"h2 windows %d-%d (stream-conn), " "h2 windows %d-%d (stream-conn), buffers %zu-%zu (stream-conn)",
"buffers %zu-%zu (stream-conn)",
ctx->tunnel.stream_id, len, nwritten, *err, ctx->tunnel.stream_id, len, nwritten, *err,
nghttp2_session_get_stream_remote_window_size( nghttp2_session_get_stream_remote_window_size(
ctx->h2, ctx->tunnel.stream_id), ctx->h2, ctx->tunnel.stream_id),
nghttp2_session_get_remote_window_size(ctx->h2), nghttp2_session_get_remote_window_size(ctx->h2),
Curl_bufq_len(&ctx->tunnel.sendbuf), Curl_bufq_len(&ctx->tunnel.sendbuf),
Curl_bufq_len(&ctx->outbufq))); Curl_bufq_len(&ctx->outbufq));
CF_DATA_RESTORE(cf, save); CF_DATA_RESTORE(cf, save);
return nwritten; return nwritten;
} }
@ -1438,8 +1432,8 @@ static bool cf_h2_proxy_is_alive(struct Curl_cfilter *cf,
CF_DATA_SAVE(save, cf, data); CF_DATA_SAVE(save, cf, data);
result = (ctx && ctx->h2 && proxy_h2_connisalive(cf, data, input_pending)); result = (ctx && ctx->h2 && proxy_h2_connisalive(cf, data, input_pending));
DEBUGF(LOG_CF(data, cf, "conn alive -> %d, input_pending=%d", CURL_TRC_CF(data, cf, "conn alive -> %d, input_pending=%d",
result, *input_pending)); result, *input_pending);
CF_DATA_RESTORE(cf, save); CF_DATA_RESTORE(cf, save);
return result; return result;
} }
@ -1447,7 +1441,7 @@ static bool cf_h2_proxy_is_alive(struct Curl_cfilter *cf,
struct Curl_cftype Curl_cft_h2_proxy = { struct Curl_cftype Curl_cft_h2_proxy = {
"H2-PROXY", "H2-PROXY",
CF_TYPE_IP_CONNECT, CF_TYPE_IP_CONNECT,
CURL_LOG_DEFAULT, CURL_LOG_LVL_NONE,
cf_h2_proxy_destroy, cf_h2_proxy_destroy,
cf_h2_proxy_connect, cf_h2_proxy_connect,
cf_h2_proxy_close, cf_h2_proxy_close,

6
lib/cf-haproxy.c
View File

@ -30,7 +30,7 @@
#include "urldata.h" #include "urldata.h"
#include "cfilters.h" #include "cfilters.h"
#include "cf-haproxy.h" #include "cf-haproxy.h"
#include "curl_log.h" #include "curl_trc.h"
#include "multiif.h" #include "multiif.h"
/* The last 3 #include files should be in this order */ /* The last 3 #include files should be in this order */
@ -157,14 +157,14 @@ static void cf_haproxy_destroy(struct Curl_cfilter *cf,
struct Curl_easy *data) struct Curl_easy *data)
{ {
(void)data; (void)data;
DEBUGF(LOG_CF(data, cf, "destroy")); CURL_TRC_CF(data, cf, "destroy");
cf_haproxy_ctx_free(cf->ctx); cf_haproxy_ctx_free(cf->ctx);
} }
static void cf_haproxy_close(struct Curl_cfilter *cf, static void cf_haproxy_close(struct Curl_cfilter *cf,
struct Curl_easy *data) struct Curl_easy *data)
{ {
DEBUGF(LOG_CF(data, cf, "close")); CURL_TRC_CF(data, cf, "close");
cf->connected = FALSE; cf->connected = FALSE;
cf_haproxy_ctx_reset(cf->ctx); cf_haproxy_ctx_reset(cf->ctx);
if(cf->next) if(cf->next)

34
lib/cf-https-connect.c
View File

@ -28,7 +28,7 @@
#include "urldata.h" #include "urldata.h"
#include <curl/curl.h> #include <curl/curl.h>
#include "curl_log.h" #include "curl_trc.h"
#include "cfilters.h" #include "cfilters.h"
#include "connect.h" #include "connect.h"
#include "multiif.h" #include "multiif.h"
@ -165,9 +165,9 @@ static CURLcode baller_connected(struct Curl_cfilter *cf,
if(winner != &ctx->h21_baller) if(winner != &ctx->h21_baller)
cf_hc_baller_reset(&ctx->h21_baller, data); cf_hc_baller_reset(&ctx->h21_baller, data);
DEBUGF(LOG_CF(data, cf, "connect+handshake %s: %dms, 1st data: %dms", CURL_TRC_CF(data, cf, "connect+handshake %s: %dms, 1st data: %dms",
winner->name, (int)Curl_timediff(Curl_now(), winner->started), winner->name, (int)Curl_timediff(Curl_now(), winner->started),
cf_hc_baller_reply_ms(winner, data))); cf_hc_baller_reply_ms(winner, data));
cf->next = winner->cf; cf->next = winner->cf;
winner->cf = NULL; winner->cf = NULL;
@ -218,16 +218,16 @@ static bool time_to_start_h21(struct Curl_cfilter *cf,
elapsed_ms = Curl_timediff(now, ctx->started); elapsed_ms = Curl_timediff(now, ctx->started);
if(elapsed_ms >= ctx->hard_eyeballs_timeout_ms) { if(elapsed_ms >= ctx->hard_eyeballs_timeout_ms) {
DEBUGF(LOG_CF(data, cf, "hard timeout of %dms reached, starting h21", CURL_TRC_CF(data, cf, "hard timeout of %dms reached, starting h21",
ctx->hard_eyeballs_timeout_ms)); ctx->hard_eyeballs_timeout_ms);
return TRUE; return TRUE;
} }
if(elapsed_ms >= ctx->soft_eyeballs_timeout_ms) { if(elapsed_ms >= ctx->soft_eyeballs_timeout_ms) {
if(cf_hc_baller_reply_ms(&ctx->h3_baller, data) < 0) { if(cf_hc_baller_reply_ms(&ctx->h3_baller, data) < 0) {
DEBUGF(LOG_CF(data, cf, "soft timeout of %dms reached, h3 has not " CURL_TRC_CF(data, cf, "soft timeout of %dms reached, h3 has not "
"seen any data, starting h21", "seen any data, starting h21",
ctx->soft_eyeballs_timeout_ms)); ctx->soft_eyeballs_timeout_ms);
return TRUE; return TRUE;
} }
/* set the effective hard timeout again */ /* set the effective hard timeout again */
@ -258,7 +258,7 @@ static CURLcode cf_hc_connect(struct Curl_cfilter *cf,
DEBUGASSERT(!ctx->h3_baller.cf); DEBUGASSERT(!ctx->h3_baller.cf);
DEBUGASSERT(!ctx->h21_baller.cf); DEBUGASSERT(!ctx->h21_baller.cf);
DEBUGASSERT(!cf->next); DEBUGASSERT(!cf->next);
DEBUGF(LOG_CF(data, cf, "connect, init")); CURL_TRC_CF(data, cf, "connect, init");
ctx->started = now; ctx->started = now;
if(ctx->h3_baller.enabled) { if(ctx->h3_baller.enabled) {
cf_hc_baller_init(&ctx->h3_baller, cf, data, "h3", TRNSPRT_QUIC); cf_hc_baller_init(&ctx->h3_baller, cf, data, "h3", TRNSPRT_QUIC);
@ -286,7 +286,7 @@ static CURLcode cf_hc_connect(struct Curl_cfilter *cf,
} }
if(cf_hc_baller_is_active(&ctx->h21_baller)) { if(cf_hc_baller_is_active(&ctx->h21_baller)) {
DEBUGF(LOG_CF(data, cf, "connect, check h21")); CURL_TRC_CF(data, cf, "connect, check h21");
result = cf_hc_baller_connect(&ctx->h21_baller, cf, data, done); result = cf_hc_baller_connect(&ctx->h21_baller, cf, data, done);
if(!result && *done) { if(!result && *done) {
result = baller_connected(cf, data, &ctx->h21_baller); result = baller_connected(cf, data, &ctx->h21_baller);
@ -297,7 +297,7 @@ static CURLcode cf_hc_connect(struct Curl_cfilter *cf,
if((!ctx->h3_baller.enabled || ctx->h3_baller.result) && if((!ctx->h3_baller.enabled || ctx->h3_baller.result) &&
(!ctx->h21_baller.enabled || ctx->h21_baller.result)) { (!ctx->h21_baller.enabled || ctx->h21_baller.result)) {
/* both failed or disabled. we give up */ /* both failed or disabled. we give up */
DEBUGF(LOG_CF(data, cf, "connect, all failed")); CURL_TRC_CF(data, cf, "connect, all failed");
result = ctx->result = ctx->h3_baller.enabled? result = ctx->result = ctx->h3_baller.enabled?
ctx->h3_baller.result : ctx->h21_baller.result; ctx->h3_baller.result : ctx->h21_baller.result;
ctx->state = CF_HC_FAILURE; ctx->state = CF_HC_FAILURE;
@ -321,7 +321,7 @@ static CURLcode cf_hc_connect(struct Curl_cfilter *cf,
} }
out: out:
DEBUGF(LOG_CF(data, cf, "connect -> %d, done=%d", result, *done)); CURL_TRC_CF(data, cf, "connect -> %d, done=%d", result, *done);
return result; return result;
} }
@ -345,7 +345,7 @@ static int cf_hc_get_select_socks(struct Curl_cfilter *cf,
if(!cf_hc_baller_is_active(b)) if(!cf_hc_baller_is_active(b))
continue; continue;
brc = Curl_conn_cf_get_select_socks(b->cf, data, bsocks); brc = Curl_conn_cf_get_select_socks(b->cf, data, bsocks);
DEBUGF(LOG_CF(data, cf, "get_selected_socks(%s) -> %x", b->name, brc)); CURL_TRC_CF(data, cf, "get_selected_socks(%s) -> %x", b->name, brc);
if(!brc) if(!brc)
continue; continue;
for(j = 0; j < MAX_SOCKSPEREASYHANDLE && s < MAX_SOCKSPEREASYHANDLE; ++j) { for(j = 0; j < MAX_SOCKSPEREASYHANDLE && s < MAX_SOCKSPEREASYHANDLE; ++j) {
@ -359,7 +359,7 @@ static int cf_hc_get_select_socks(struct Curl_cfilter *cf,
} }
} }
} }
DEBUGF(LOG_CF(data, cf, "get_selected_socks -> %x", rc)); CURL_TRC_CF(data, cf, "get_selected_socks -> %x", rc);
return rc; return rc;
} }
@ -371,7 +371,7 @@ static bool cf_hc_data_pending(struct Curl_cfilter *cf,
if(cf->connected) if(cf->connected)
return cf->next->cft->has_data_pending(cf->next, data); return cf->next->cft->has_data_pending(cf->next, data);
DEBUGF(LOG_CF((struct Curl_easy *)data, cf, "data_pending")); CURL_TRC_CF((struct Curl_easy *)data, cf, "data_pending");
return cf_hc_baller_data_pending(&ctx->h3_baller, data) return cf_hc_baller_data_pending(&ctx->h3_baller, data)
|| cf_hc_baller_data_pending(&ctx->h21_baller, data); || cf_hc_baller_data_pending(&ctx->h21_baller, data);
} }
@ -427,7 +427,7 @@ static CURLcode cf_hc_query(struct Curl_cfilter *cf,
static void cf_hc_close(struct Curl_cfilter *cf, struct Curl_easy *data) static void cf_hc_close(struct Curl_cfilter *cf, struct Curl_easy *data)
{ {
DEBUGF(LOG_CF(data, cf, "close")); CURL_TRC_CF(data, cf, "close");
cf_hc_reset(cf, data); cf_hc_reset(cf, data);
cf->connected = FALSE; cf->connected = FALSE;
@ -442,7 +442,7 @@ static void cf_hc_destroy(struct Curl_cfilter *cf, struct Curl_easy *data)
struct cf_hc_ctx *ctx = cf->ctx; struct cf_hc_ctx *ctx = cf->ctx;
(void)data; (void)data;
DEBUGF(LOG_CF(data, cf, "destroy")); CURL_TRC_CF(data, cf, "destroy");
cf_hc_reset(cf, data); cf_hc_reset(cf, data);
Curl_safefree(ctx); Curl_safefree(ctx);
} }
@ -450,7 +450,7 @@ static void cf_hc_destroy(struct Curl_cfilter *cf, struct Curl_easy *data)
struct Curl_cftype Curl_cft_http_connect = { struct Curl_cftype Curl_cft_http_connect = {
"HTTPS-CONNECT", "HTTPS-CONNECT",
0, 0,
CURL_LOG_DEFAULT, CURL_LOG_LVL_NONE,
cf_hc_destroy, cf_hc_destroy,
cf_hc_connect, cf_hc_connect,
cf_hc_close, cf_hc_close,

80
lib/cf-socket.c
View File

@ -632,7 +632,7 @@ static CURLcode bindlocal(struct Curl_easy *data, struct connectdata *conn,
port++; /* try next port */ port++; /* try next port */
if(port == 0) if(port == 0)
break; break;
infof(data, "Bind to local port %hu failed, trying next", port - 1); infof(data, "Bind to local port %d failed, trying next", port - 1);
/* We re-use/clobber the port variable here below */ /* We re-use/clobber the port variable here below */
if(sock->sa_family == AF_INET) if(sock->sa_family == AF_INET)
si4->sin_port = ntohs(port); si4->sin_port = ntohs(port);
@ -836,8 +836,8 @@ static ssize_t nw_in_read(void *reader_ctx,
nread = -1; nread = -1;
} }
} }
DEBUGF(LOG_CF(rctx->data, rctx->cf, "nw_in_read(len=%zu) -> %d, err=%d", CURL_TRC_CF(rctx->data, rctx->cf, "nw_in_read(len=%zu) -> %d, err=%d",
len, (int)nread, *err)); len, (int)nread, *err);
return nread; return nread;
} }
@ -852,14 +852,14 @@ static void cf_socket_close(struct Curl_cfilter *cf, struct Curl_easy *data)
* closed it) and we just forget about it. * closed it) and we just forget about it.
*/ */
if(ctx->sock == cf->conn->sock[cf->sockindex]) { if(ctx->sock == cf->conn->sock[cf->sockindex]) {
DEBUGF(LOG_CF(data, cf, "cf_socket_close(%" CURL_FORMAT_SOCKET_T CURL_TRC_CF(data, cf, "cf_socket_close(%" CURL_FORMAT_SOCKET_T
", active)", ctx->sock)); ", active)", ctx->sock);
socket_close(data, cf->conn, !ctx->accepted, ctx->sock); socket_close(data, cf->conn, !ctx->accepted, ctx->sock);
cf->conn->sock[cf->sockindex] = CURL_SOCKET_BAD; cf->conn->sock[cf->sockindex] = CURL_SOCKET_BAD;
} }
else { else {
DEBUGF(LOG_CF(data, cf, "cf_socket_close(%" CURL_FORMAT_SOCKET_T CURL_TRC_CF(data, cf, "cf_socket_close(%" CURL_FORMAT_SOCKET_T
") no longer at conn->sock[], discarding", ctx->sock)); ") no longer at conn->sock[], discarding", ctx->sock);
/* TODO: we do not want this to happen. Need to check which /* TODO: we do not want this to happen. Need to check which
* code is messing with conn->sock[cf->sockindex] */ * code is messing with conn->sock[cf->sockindex] */
} }
@ -869,8 +869,8 @@ static void cf_socket_close(struct Curl_cfilter *cf, struct Curl_easy *data)
} }
else { else {
/* this is our local socket, we did never publish it */ /* this is our local socket, we did never publish it */
DEBUGF(LOG_CF(data, cf, "cf_socket_close(%" CURL_FORMAT_SOCKET_T CURL_TRC_CF(data, cf, "cf_socket_close(%" CURL_FORMAT_SOCKET_T
", not active)", ctx->sock)); ", not active)", ctx->sock);
socket_close(data, cf->conn, !ctx->accepted, ctx->sock); socket_close(data, cf->conn, !ctx->accepted, ctx->sock);
ctx->sock = CURL_SOCKET_BAD; ctx->sock = CURL_SOCKET_BAD;
} }
@ -889,7 +889,7 @@ static void cf_socket_destroy(struct Curl_cfilter *cf, struct Curl_easy *data)
struct cf_socket_ctx *ctx = cf->ctx; struct cf_socket_ctx *ctx = cf->ctx;
cf_socket_close(cf, data); cf_socket_close(cf, data);
DEBUGF(LOG_CF(data, cf, "destroy")); CURL_TRC_CF(data, cf, "destroy");
Curl_bufq_free(&ctx->recvbuf); Curl_bufq_free(&ctx->recvbuf);
free(ctx); free(ctx);
cf->ctx = NULL; cf->ctx = NULL;
@ -1047,8 +1047,8 @@ out:
ctx->connected_at = Curl_now(); ctx->connected_at = Curl_now();
cf->connected = TRUE; cf->connected = TRUE;
} }
DEBUGF(LOG_CF(data, cf, "cf_socket_open() -> %d, fd=%" CURL_FORMAT_SOCKET_T, CURL_TRC_CF(data, cf, "cf_socket_open() -> %d, fd=%" CURL_FORMAT_SOCKET_T,
result, ctx->sock)); result, ctx->sock);
return result; return result;
} }
@ -1155,7 +1155,7 @@ static CURLcode cf_tcp_connect(struct Curl_cfilter *cf,
rc = SOCKET_WRITABLE(ctx->sock, 0); rc = SOCKET_WRITABLE(ctx->sock, 0);
if(rc == 0) { /* no connection yet */ if(rc == 0) { /* no connection yet */
DEBUGF(LOG_CF(data, cf, "not connected yet")); CURL_TRC_CF(data, cf, "not connected yet");
return CURLE_OK; return CURLE_OK;
} }
else if(rc == CURL_CSELECT_OUT || cf->conn->bits.tcp_fastopen) { else if(rc == CURL_CSELECT_OUT || cf->conn->bits.tcp_fastopen) {
@ -1165,7 +1165,7 @@ static CURLcode cf_tcp_connect(struct Curl_cfilter *cf,
set_local_ip(cf, data); set_local_ip(cf, data);
*done = TRUE; *done = TRUE;
cf->connected = TRUE; cf->connected = TRUE;
DEBUGF(LOG_CF(data, cf, "connected")); CURL_TRC_CF(data, cf, "connected");
return CURLE_OK; return CURLE_OK;
} }
} }
@ -1288,8 +1288,8 @@ static ssize_t cf_socket_send(struct Curl_cfilter *cf, struct Curl_easy *data,
} }
} }
DEBUGF(LOG_CF(data, cf, "send(len=%zu) -> %d, err=%d", CURL_TRC_CF(data, cf, "send(len=%zu) -> %d, err=%d",
len, (int)nwritten, *err)); len, (int)nwritten, *err);
cf->conn->sock[cf->sockindex] = fdsave; cf->conn->sock[cf->sockindex] = fdsave;
return nwritten; return nwritten;
} }
@ -1307,7 +1307,7 @@ static ssize_t cf_socket_recv(struct Curl_cfilter *cf, struct Curl_easy *data,
cf->conn->sock[cf->sockindex] = ctx->sock; cf->conn->sock[cf->sockindex] = ctx->sock;
if(ctx->buffer_recv && !Curl_bufq_is_empty(&ctx->recvbuf)) { if(ctx->buffer_recv && !Curl_bufq_is_empty(&ctx->recvbuf)) {
DEBUGF(LOG_CF(data, cf, "recv from buffer")); CURL_TRC_CF(data, cf, "recv from buffer");
nread = Curl_bufq_read(&ctx->recvbuf, (unsigned char *)buf, len, err); nread = Curl_bufq_read(&ctx->recvbuf, (unsigned char *)buf, len, err);
} }
else { else {
@ -1324,7 +1324,7 @@ static ssize_t cf_socket_recv(struct Curl_cfilter *cf, struct Curl_easy *data,
if(nwritten < 0 && !Curl_bufq_is_empty(&ctx->recvbuf)) { if(nwritten < 0 && !Curl_bufq_is_empty(&ctx->recvbuf)) {
/* we have a partial read with an error. need to deliver /* we have a partial read with an error. need to deliver
* what we got, return the error later. */ * what we got, return the error later. */
DEBUGF(LOG_CF(data, cf, "partial read: empty buffer first")); CURL_TRC_CF(data, cf, "partial read: empty buffer first");
nread = Curl_bufq_read(&ctx->recvbuf, (unsigned char *)buf, len, err); nread = Curl_bufq_read(&ctx->recvbuf, (unsigned char *)buf, len, err);
} }
else if(nwritten < 0) { else if(nwritten < 0) {
@ -1337,7 +1337,7 @@ static ssize_t cf_socket_recv(struct Curl_cfilter *cf, struct Curl_easy *data,
nread = 0; nread = 0;
} }
else { else {
DEBUGF(LOG_CF(data, cf, "buffered %zd additional bytes", nwritten)); CURL_TRC_CF(data, cf, "buffered %zd additional bytes", nwritten);
nread = Curl_bufq_read(&ctx->recvbuf, (unsigned char *)buf, len, err); nread = Curl_bufq_read(&ctx->recvbuf, (unsigned char *)buf, len, err);
} }
} }
@ -1347,8 +1347,8 @@ static ssize_t cf_socket_recv(struct Curl_cfilter *cf, struct Curl_easy *data,
} }
out: out:
DEBUGF(LOG_CF(data, cf, "recv(len=%zu) -> %d, err=%d", len, (int)nread, CURL_TRC_CF(data, cf, "recv(len=%zu) -> %d, err=%d", len, (int)nread,
*err)); *err);
if(nread > 0 && !ctx->got_first_byte) { if(nread > 0 && !ctx->got_first_byte) {
ctx->first_byte_at = Curl_now(); ctx->first_byte_at = Curl_now();
ctx->got_first_byte = TRUE; ctx->got_first_byte = TRUE;
@ -1455,19 +1455,19 @@ static bool cf_socket_conn_is_alive(struct Curl_cfilter *cf,
r = Curl_poll(pfd, 1, 0); r = Curl_poll(pfd, 1, 0);
if(r < 0) { if(r < 0) {
DEBUGF(LOG_CF(data, cf, "is_alive: poll error, assume dead")); CURL_TRC_CF(data, cf, "is_alive: poll error, assume dead");
return FALSE; return FALSE;
} }
else if(r == 0) { else if(r == 0) {
DEBUGF(LOG_CF(data, cf, "is_alive: poll timeout, assume alive")); CURL_TRC_CF(data, cf, "is_alive: poll timeout, assume alive");
return TRUE; return TRUE;
} }
else if(pfd[0].revents & (POLLERR|POLLHUP|POLLPRI|POLLNVAL)) { else if(pfd[0].revents & (POLLERR|POLLHUP|POLLPRI|POLLNVAL)) {
DEBUGF(LOG_CF(data, cf, "is_alive: err/hup/etc events, assume dead")); CURL_TRC_CF(data, cf, "is_alive: err/hup/etc events, assume dead");
return FALSE; return FALSE;
} }
DEBUGF(LOG_CF(data, cf, "is_alive: valid events, looks alive")); CURL_TRC_CF(data, cf, "is_alive: valid events, looks alive");
*input_pending = TRUE; *input_pending = TRUE;
return TRUE; return TRUE;
} }
@ -1520,7 +1520,7 @@ static CURLcode cf_socket_query(struct Curl_cfilter *cf,
struct Curl_cftype Curl_cft_tcp = { struct Curl_cftype Curl_cft_tcp = {
"TCP", "TCP",
CF_TYPE_IP_CONNECT, CF_TYPE_IP_CONNECT,
CURL_LOG_DEFAULT, CURL_LOG_LVL_NONE,
cf_socket_destroy, cf_socket_destroy,
cf_tcp_connect, cf_tcp_connect,
cf_socket_close, cf_socket_close,
@ -1581,10 +1581,10 @@ static CURLcode cf_udp_setup_quic(struct Curl_cfilter *cf,
return socket_connect_result(data, ctx->r_ip, SOCKERRNO); return socket_connect_result(data, ctx->r_ip, SOCKERRNO);
} }
set_local_ip(cf, data); set_local_ip(cf, data);
DEBUGF(LOG_CF(data, cf, "%s socket %" CURL_FORMAT_SOCKET_T CURL_TRC_CF(data, cf, "%s socket %" CURL_FORMAT_SOCKET_T
" connected: [%s:%d] -> [%s:%d]", " connected: [%s:%d] -> [%s:%d]",
(ctx->transport == TRNSPRT_QUIC)? "QUIC" : "UDP", (ctx->transport == TRNSPRT_QUIC)? "QUIC" : "UDP",
ctx->sock, ctx->l_ip, ctx->l_port, ctx->r_ip, ctx->r_port)); ctx->sock, ctx->l_ip, ctx->l_port, ctx->r_ip, ctx->r_port);
(void)curlx_nonblock(ctx->sock, TRUE); (void)curlx_nonblock(ctx->sock, TRUE);
switch(ctx->addr.family) { switch(ctx->addr.family) {
@ -1624,7 +1624,7 @@ static CURLcode cf_udp_connect(struct Curl_cfilter *cf,
if(ctx->sock == CURL_SOCKET_BAD) { if(ctx->sock == CURL_SOCKET_BAD) {
result = cf_socket_open(cf, data); result = cf_socket_open(cf, data);
if(result) { if(result) {
DEBUGF(LOG_CF(data, cf, "cf_udp_connect(), open failed -> %d", result)); CURL_TRC_CF(data, cf, "cf_udp_connect(), open failed -> %d", result);
goto out; goto out;
} }
@ -1632,13 +1632,13 @@ static CURLcode cf_udp_connect(struct Curl_cfilter *cf,
result = cf_udp_setup_quic(cf, data); result = cf_udp_setup_quic(cf, data);
if(result) if(result)
goto out; goto out;
DEBUGF(LOG_CF(data, cf, "cf_udp_connect(), opened socket=%" CURL_TRC_CF(data, cf, "cf_udp_connect(), opened socket=%"
CURL_FORMAT_SOCKET_T " (%s:%d)", CURL_FORMAT_SOCKET_T " (%s:%d)",
ctx->sock, ctx->l_ip, ctx->l_port)); ctx->sock, ctx->l_ip, ctx->l_port);
} }
else { else {
DEBUGF(LOG_CF(data, cf, "cf_udp_connect(), opened socket=%" CURL_TRC_CF(data, cf, "cf_udp_connect(), opened socket=%"
CURL_FORMAT_SOCKET_T " (unconnected)", ctx->sock)); CURL_FORMAT_SOCKET_T " (unconnected)", ctx->sock);
} }
*done = TRUE; *done = TRUE;
cf->connected = TRUE; cf->connected = TRUE;
@ -1650,7 +1650,7 @@ out:
struct Curl_cftype Curl_cft_udp = { struct Curl_cftype Curl_cft_udp = {
"UDP", "UDP",
CF_TYPE_IP_CONNECT, CF_TYPE_IP_CONNECT,
CURL_LOG_DEFAULT, CURL_LOG_LVL_NONE,
cf_socket_destroy, cf_socket_destroy,
cf_udp_connect, cf_udp_connect,
cf_socket_close, cf_socket_close,
@ -1701,7 +1701,7 @@ out:
struct Curl_cftype Curl_cft_unix = { struct Curl_cftype Curl_cft_unix = {
"UNIX", "UNIX",
CF_TYPE_IP_CONNECT, CF_TYPE_IP_CONNECT,
CURL_LOG_DEFAULT, CURL_LOG_LVL_NONE,
cf_socket_destroy, cf_socket_destroy,
cf_tcp_connect, cf_tcp_connect,
cf_socket_close, cf_socket_close,
@ -1765,7 +1765,7 @@ static CURLcode cf_tcp_accept_connect(struct Curl_cfilter *cf,
struct Curl_cftype Curl_cft_tcp_accept = { struct Curl_cftype Curl_cft_tcp_accept = {
"TCP-ACCEPT", "TCP-ACCEPT",
CF_TYPE_IP_CONNECT, CF_TYPE_IP_CONNECT,
CURL_LOG_DEFAULT, CURL_LOG_LVL_NONE,
cf_socket_destroy, cf_socket_destroy,
cf_tcp_accept_connect, cf_tcp_accept_connect,
cf_socket_close, cf_socket_close,
@ -1810,8 +1810,8 @@ CURLcode Curl_conn_tcp_listen_set(struct Curl_easy *data,
ctx->active = TRUE; ctx->active = TRUE;
ctx->connected_at = Curl_now(); ctx->connected_at = Curl_now();
cf->connected = TRUE; cf->connected = TRUE;
DEBUGF(LOG_CF(data, cf, "Curl_conn_tcp_listen_set(%" CURL_TRC_CF(data, cf, "Curl_conn_tcp_listen_set(%"
CURL_FORMAT_SOCKET_T ")", ctx->sock)); CURL_FORMAT_SOCKET_T ")", ctx->sock);
out: out:
if(result) { if(result) {
@ -1875,9 +1875,9 @@ CURLcode Curl_conn_tcp_accepted_set(struct Curl_easy *data,
ctx->accepted = TRUE; ctx->accepted = TRUE;
ctx->connected_at = Curl_now(); ctx->connected_at = Curl_now();
cf->connected = TRUE; cf->connected = TRUE;
DEBUGF(LOG_CF(data, cf, "accepted_set(sock=%" CURL_FORMAT_SOCKET_T CURL_TRC_CF(data, cf, "accepted_set(sock=%" CURL_FORMAT_SOCKET_T
", remote=%s port=%d)", ", remote=%s port=%d)",
ctx->sock, ctx->r_ip, ctx->r_port)); ctx->sock, ctx->r_ip, ctx->r_port);
return CURLE_OK; return CURLE_OK;
} }

2
lib/cfilters.c
View File

@ -238,7 +238,7 @@ void Curl_conn_cf_add(struct Curl_easy *data,
cf->conn = conn; cf->conn = conn;
cf->sockindex = index; cf->sockindex = index;
conn->cfilter[index] = cf; conn->cfilter[index] = cf;
DEBUGF(LOG_CF(data, cf, "added")); CURL_TRC_CF(data, cf, "added");
} }
void Curl_conn_cf_insert_after(struct Curl_cfilter *cf_at, void Curl_conn_cf_insert_after(struct Curl_cfilter *cf_at,

46
lib/connect.c
View File

@ -475,7 +475,7 @@ static void baller_initiate(struct Curl_cfilter *cf,
out: out:
if(result) { if(result) {
DEBUGF(LOG_CF(data, cf, "%s failed", baller->name)); CURL_TRC_CF(data, cf, "%s failed", baller->name);
baller_close(baller, data); baller_close(baller, data);
} }
if(cf_prev) if(cf_prev)
@ -601,8 +601,8 @@ evaluate:
continue; continue;
} }
baller->result = baller_connect(cf, data, baller, &now, connected); baller->result = baller_connect(cf, data, baller, &now, connected);
DEBUGF(LOG_CF(data, cf, "%s connect -> %d, connected=%d", CURL_TRC_CF(data, cf, "%s connect -> %d, connected=%d",
baller->name, baller->result, *connected)); baller->name, baller->result, *connected);
if(!baller->result) { if(!baller->result) {
if(*connected) { if(*connected) {
@ -623,11 +623,11 @@ evaluate:
} }
baller_start_next(cf, data, baller, Curl_timeleft(data, &now, TRUE)); baller_start_next(cf, data, baller, Curl_timeleft(data, &now, TRUE));
if(baller->is_done) { if(baller->is_done) {
DEBUGF(LOG_CF(data, cf, "%s done", baller->name)); CURL_TRC_CF(data, cf, "%s done", baller->name);
} }
else { else {
/* next attempt was started */ /* next attempt was started */
DEBUGF(LOG_CF(data, cf, "%s trying next", baller->name)); CURL_TRC_CF(data, cf, "%s trying next", baller->name);
++ongoing; ++ongoing;
} }
} }
@ -661,12 +661,12 @@ evaluate:
Curl_timediff(now, ctx->started) >= baller->delay_ms) { Curl_timediff(now, ctx->started) >= baller->delay_ms) {
baller_start(cf, data, baller, Curl_timeleft(data, &now, TRUE)); baller_start(cf, data, baller, Curl_timeleft(data, &now, TRUE));
if(baller->is_done) { if(baller->is_done) {
DEBUGF(LOG_CF(data, cf, "%s done", baller->name)); CURL_TRC_CF(data, cf, "%s done", baller->name);
} }
else { else {
DEBUGF(LOG_CF(data, cf, "%s starting (timeout=%" CURL_TRC_CF(data, cf, "%s starting (timeout=%"
CURL_FORMAT_TIMEDIFF_T "ms)", CURL_FORMAT_TIMEDIFF_T "ms)",
baller->name, baller->timeoutms)); baller->name, baller->timeoutms);
++ongoing; ++ongoing;
++added; ++added;
} }
@ -683,14 +683,14 @@ evaluate:
} }
/* all ballers have failed to connect. */ /* all ballers have failed to connect. */
DEBUGF(LOG_CF(data, cf, "all eyeballers failed")); CURL_TRC_CF(data, cf, "all eyeballers failed");
result = CURLE_COULDNT_CONNECT; result = CURLE_COULDNT_CONNECT;
for(i = 0; i < sizeof(ctx->baller)/sizeof(ctx->baller[0]); i++) { for(i = 0; i < sizeof(ctx->baller)/sizeof(ctx->baller[0]); i++) {
struct eyeballer *baller = ctx->baller[i]; struct eyeballer *baller = ctx->baller[i];
DEBUGF(LOG_CF(data, cf, "%s assess started=%d, result=%d", CURL_TRC_CF(data, cf, "%s assess started=%d, result=%d",
baller?baller->name:NULL, baller?baller->name:NULL,
baller?baller->has_started:0, baller?baller->has_started:0,
baller?baller->result:0)); baller?baller->result:0);
if(baller && baller->has_started && baller->result) { if(baller && baller->has_started && baller->result) {
result = baller->result; result = baller->result;
break; break;
@ -803,9 +803,9 @@ static CURLcode start_connect(struct Curl_cfilter *cf,
timeout_ms, EXPIRE_DNS_PER_NAME); timeout_ms, EXPIRE_DNS_PER_NAME);
if(result) if(result)
return result; return result;
DEBUGF(LOG_CF(data, cf, "created %s (timeout %" CURL_TRC_CF(data, cf, "created %s (timeout %"
CURL_FORMAT_TIMEDIFF_T "ms)", CURL_FORMAT_TIMEDIFF_T "ms)",
ctx->baller[0]->name, ctx->baller[0]->timeoutms)); ctx->baller[0]->name, ctx->baller[0]->timeoutms);
if(addr1) { if(addr1) {
/* second one gets a delayed start */ /* second one gets a delayed start */
result = eyeballer_new(&ctx->baller[1], ctx->cf_create, addr1, ai_family1, result = eyeballer_new(&ctx->baller[1], ctx->cf_create, addr1, ai_family1,
@ -815,9 +815,9 @@ static CURLcode start_connect(struct Curl_cfilter *cf,
timeout_ms, EXPIRE_DNS_PER_NAME2); timeout_ms, EXPIRE_DNS_PER_NAME2);
if(result) if(result)
return result; return result;
DEBUGF(LOG_CF(data, cf, "created %s (timeout %" CURL_TRC_CF(data, cf, "created %s (timeout %"
CURL_FORMAT_TIMEDIFF_T "ms)", CURL_FORMAT_TIMEDIFF_T "ms)",
ctx->baller[1]->name, ctx->baller[1]->timeoutms)); ctx->baller[1]->name, ctx->baller[1]->timeoutms);
} }
Curl_expire(data, data->set.happy_eyeballs_timeout, Curl_expire(data, data->set.happy_eyeballs_timeout,
@ -931,7 +931,7 @@ static void cf_he_close(struct Curl_cfilter *cf,
{ {
struct cf_he_ctx *ctx = cf->ctx; struct cf_he_ctx *ctx = cf->ctx;
DEBUGF(LOG_CF(data, cf, "close")); CURL_TRC_CF(data, cf, "close");
cf_he_ctx_clear(cf, data); cf_he_ctx_clear(cf, data);
cf->connected = FALSE; cf->connected = FALSE;
ctx->state = SCFST_INIT; ctx->state = SCFST_INIT;
@ -1007,7 +1007,7 @@ static CURLcode cf_he_query(struct Curl_cfilter *cf,
} }
} }
*pres1 = reply_ms; *pres1 = reply_ms;
DEBUGF(LOG_CF(data, cf, "query connect reply: %dms", *pres1)); CURL_TRC_CF(data, cf, "query connect reply: %dms", *pres1);
return CURLE_OK; return CURLE_OK;
} }
case CF_QUERY_TIMER_CONNECT: { case CF_QUERY_TIMER_CONNECT: {
@ -1034,7 +1034,7 @@ static void cf_he_destroy(struct Curl_cfilter *cf, struct Curl_easy *data)
{ {
struct cf_he_ctx *ctx = cf->ctx; struct cf_he_ctx *ctx = cf->ctx;
DEBUGF(LOG_CF(data, cf, "destroy")); CURL_TRC_CF(data, cf, "destroy");
if(ctx) { if(ctx) {
cf_he_ctx_clear(cf, data); cf_he_ctx_clear(cf, data);
} }
@ -1045,7 +1045,7 @@ static void cf_he_destroy(struct Curl_cfilter *cf, struct Curl_easy *data)
struct Curl_cftype Curl_cft_happy_eyeballs = { struct Curl_cftype Curl_cft_happy_eyeballs = {
"HAPPY-EYEBALLS", "HAPPY-EYEBALLS",
0, 0,
CURL_LOG_DEFAULT, CURL_LOG_LVL_NONE,
cf_he_destroy, cf_he_destroy,
cf_he_connect, cf_he_connect,
cf_he_close, cf_he_close,
@ -1148,7 +1148,7 @@ static CURLcode cf_he_insert_after(struct Curl_cfilter *cf_at,
DEBUGASSERT(cf_at); DEBUGASSERT(cf_at);
cf_create = get_cf_create(transport); cf_create = get_cf_create(transport);
if(!cf_create) { if(!cf_create) {
DEBUGF(LOG_CF(data, cf_at, "unsupported transport type %d", transport)); CURL_TRC_CF(data, cf_at, "unsupported transport type %d", transport);
return CURLE_UNSUPPORTED_PROTOCOL; return CURLE_UNSUPPORTED_PROTOCOL;
} }
result = cf_happy_eyeballs_create(&cf, data, cf_at->conn, result = cf_happy_eyeballs_create(&cf, data, cf_at->conn,
@ -1286,7 +1286,7 @@ static void cf_setup_close(struct Curl_cfilter *cf,
{ {
struct cf_setup_ctx *ctx = cf->ctx; struct cf_setup_ctx *ctx = cf->ctx;
DEBUGF(LOG_CF(data, cf, "close")); CURL_TRC_CF(data, cf, "close");
cf->connected = FALSE; cf->connected = FALSE;
ctx->state = CF_SETUP_INIT; ctx->state = CF_SETUP_INIT;
@ -1301,7 +1301,7 @@ static void cf_setup_destroy(struct Curl_cfilter *cf, struct Curl_easy *data)
struct cf_setup_ctx *ctx = cf->ctx; struct cf_setup_ctx *ctx = cf->ctx;
(void)data; (void)data;
DEBUGF(LOG_CF(data, cf, "destroy")); CURL_TRC_CF(data, cf, "destroy");
Curl_safefree(ctx); Curl_safefree(ctx);
} }
@ -1309,7 +1309,7 @@ static void cf_setup_destroy(struct Curl_cfilter *cf, struct Curl_easy *data)
struct Curl_cftype Curl_cft_setup = { struct Curl_cftype Curl_cft_setup = {
"SETUP", "SETUP",
0, 0,
CURL_LOG_DEFAULT, CURL_LOG_LVL_NONE,
cf_setup_destroy, cf_setup_destroy,
cf_setup_connect, cf_setup_connect,
cf_setup_close, cf_setup_close,

121
lib/curl_log.h
View File

@ -1,121 +0,0 @@
#ifndef HEADER_CURL_LOG_H
#define HEADER_CURL_LOG_H
/***************************************************************************
* _ _ ____ _
* Project ___| | | | _ \| |
* / __| | | | |_) | |
* | (__| |_| | _ <| |___
* \___|\___/|_| \_\_____|
*
* Copyright (C) Daniel Stenberg, <daniel@haxx.se>, et al.
*
* This software is licensed as described in the file COPYING, which
* you should have received as part of this distribution. The terms
* are also available at https://curl.se/docs/copyright.html.
*
* You may opt to use, copy, modify, merge, publish, distribute and/or sell
* copies of the Software, and permit persons to whom the Software is
* furnished to do so, under the terms of the COPYING file.
*
* This software is distributed on an "AS IS" basis, WITHOUT WARRANTY OF ANY
* KIND, either express or implied.
*
* SPDX-License-Identifier: curl
*
***************************************************************************/
struct Curl_easy;
struct Curl_cfilter;
/**
* Init logging, return != 0 on failure.
*/
CURLcode Curl_log_init(void);
void Curl_infof(struct Curl_easy *, const char *fmt, ...);
void Curl_failf(struct Curl_easy *, const char *fmt, ...);
#if defined(CURL_DISABLE_VERBOSE_STRINGS)
#if defined(HAVE_VARIADIC_MACROS_C99)
#define infof(...) Curl_nop_stmt
#elif defined(HAVE_VARIADIC_MACROS_GCC)
#define infof(x...) Curl_nop_stmt
#else
#error "missing VARIADIC macro define, fix and rebuild!"
#endif
#else /* CURL_DISABLE_VERBOSE_STRINGS */
#define infof Curl_infof
#endif /* CURL_DISABLE_VERBOSE_STRINGS */
#define failf Curl_failf
#define CURL_LOG_DEFAULT 0
#define CURL_LOG_DEBUG 1
#define CURL_LOG_TRACE 2
/* the function used to output verbose information */
void Curl_debug(struct Curl_easy *data, curl_infotype type,
char *ptr, size_t size);
#ifdef DEBUGBUILD
/* explainer: we have some mix configuration and werror settings
* that define HAVE_VARIADIC_MACROS_C99 even though C89 is enforced
* on gnuc and some other compiler. Need to treat carefully.
*/
#if defined(HAVE_VARIADIC_MACROS_C99) && \
defined(__STDC_VERSION__) && (__STDC_VERSION__ >= 199901L)
#define LOG_CF(data, cf, ...) \
do { if(Curl_log_cf_is_debug(cf, data)) \
Curl_log_cf_debug(data, cf, __VA_ARGS__); } while(0)
#else
#define LOG_CF Curl_log_cf_debug
#endif
void Curl_log_cf_debug(struct Curl_easy *data, struct Curl_cfilter *cf,
#if defined(__GNUC__) && !defined(printf) && \
defined(__STDC_VERSION__) && (__STDC_VERSION__ >= 199901L) && \
!defined(__MINGW32__)
const char *fmt, ...)
__attribute__((format(printf, 3, 4)));
#else
const char *fmt, ...);
#endif
#define Curl_log_cf_is_debug(cf, data) \
((data) && (data)->set.verbose && \
(cf) && (cf)->cft->log_level >= CURL_LOG_DEBUG)
#else /* !DEBUGBUILD */
#if defined(HAVE_VARIADIC_MACROS_C99) && \
defined(__STDC_VERSION__) && (__STDC_VERSION__ >= 199901L)
#define LOG_CF(...) Curl_nop_stmt
#define Curl_log_cf_debug(...) Curl_nop_stmt
#elif defined(HAVE_VARIADIC_MACROS_GCC) && \
defined(__STDC_VERSION__) && (__STDC_VERSION__ >= 199901L)
#define LOG_CF(x...) Curl_nop_stmt
#define Curl_log_cf_debug(x...) Curl_nop_stmt
#else
#define LOG_CF Curl_log_cf_debug
/* without c99, we seem unable to completely define away this function. */
void Curl_log_cf_debug(struct Curl_easy *data, struct Curl_cfilter *cf,
const char *fmt, ...);
#endif
#define Curl_log_cf_is_debug(x,y) ((void)(x), (void)(y), FALSE)
#endif /* !DEBUGBUILD */
#define LOG_CF_IS_DEBUG(cf, data) Curl_log_cf_is_debug(cf, data)
#endif /* HEADER_CURL_LOG_H */

59
lib/curl_log.c → lib/curl_trc.c
View File

@ -26,7 +26,7 @@
#include <curl/curl.h> #include <curl/curl.h>
#include "curl_log.h" #include "curl_trc.h"
#include "urldata.h" #include "urldata.h"
#include "easyif.h" #include "easyif.h"
#include "cfilters.h" #include "cfilters.h"
@ -124,13 +124,13 @@ void Curl_infof(struct Curl_easy *data, const char *fmt, ...)
} }
} }
#ifdef DEBUGBUILD #if !defined(CURL_DISABLE_VERBOSE_STRINGS)
void Curl_log_cf_debug(struct Curl_easy *data, struct Curl_cfilter *cf, void Curl_trc_cf_infof(struct Curl_easy *data, struct Curl_cfilter *cf,
const char *fmt, ...) const char *fmt, ...)
{ {
DEBUGASSERT(cf); DEBUGASSERT(cf);
if(data && Curl_log_cf_is_debug(cf, data)) { if(data && Curl_trc_cf_is_verbose(cf, data)) {
va_list ap; va_list ap;
int len; int len;
char buffer[MAXINFO + 2]; char buffer[MAXINFO + 2];
@ -179,44 +179,67 @@ static struct Curl_cftype *cf_types[] = {
NULL, NULL,
}; };
#ifndef ARRAYSIZE CURLcode Curl_trc_opt(const char *config)
#define ARRAYSIZE(A) (sizeof(A)/sizeof((A)[0]))
#endif
CURLcode Curl_log_init(void)
{ {
const char *setting = getenv("CURL_DEBUG");
if(setting) {
char *token, *tok_buf, *tmp; char *token, *tok_buf, *tmp;
size_t i; size_t i;
int lvl;
tmp = strdup(setting); tmp = strdup(config);
if(!tmp) if(!tmp)
return CURLE_OUT_OF_MEMORY; return CURLE_OUT_OF_MEMORY;
token = strtok_r(tmp, ", ", &tok_buf); token = strtok_r(tmp, ", ", &tok_buf);
while(token) { while(token) {
switch(*token) {
case '-':
lvl = CURL_LOG_LVL_NONE;
++token;
break;
case '+':
lvl = CURL_LOG_LVL_INFO;
++token;
break;
default:
lvl = CURL_LOG_LVL_INFO;
break;
}
for(i = 0; cf_types[i]; ++i) { for(i = 0; cf_types[i]; ++i) {
if(strcasecompare(token, cf_types[i]->name)) { if(strcasecompare(token, "all")) {
cf_types[i]->log_level = CURL_LOG_DEBUG; cf_types[i]->log_level = lvl;
}
else if(strcasecompare(token, cf_types[i]->name)) {
cf_types[i]->log_level = lvl;
break; break;
} }
} }
token = strtok_r(NULL, ", ", &tok_buf); token = strtok_r(NULL, ", ", &tok_buf);
} }
free(tmp); free(tmp);
}
return CURLE_OK; return CURLE_OK;
} }
#else /* DEBUGBUILD */
CURLcode Curl_log_init(void) CURLcode Curl_trc_init(void)
{
#ifdef DEBUGBUILD
/* WIP: we use the auto-init from an env var only in DEBUG builds for
* convenience. */
const char *config = getenv("CURL_DEBUG");
if(config) {
return Curl_trc_opt(config);
}
#endif
return CURLE_OK;
}
#else /* !CURL_DISABLE_VERBOSE_STRINGS) */
CURLcode Curl_trc_init(void)
{ {
return CURLE_OK; return CURLE_OK;
} }
#if !defined(__STDC_VERSION__) || (__STDC_VERSION__ < 199901L) #if !defined(__STDC_VERSION__) || (__STDC_VERSION__ < 199901L)
void Curl_log_cf_debug(struct Curl_easy *data, struct Curl_cfilter *cf, void Curl_trc_cf_infof(struct Curl_easy *data, struct Curl_cfilter *cf,
const char *fmt, ...) const char *fmt, ...)
{ {
(void)data; (void)data;

150
lib/curl_trc.h Normal file
View File

@ -0,0 +1,150 @@
#ifndef HEADER_CURL_TRC_H
#define HEADER_CURL_TRC_H
/***************************************************************************
* _ _ ____ _
* Project ___| | | | _ \| |
* / __| | | | |_) | |
* | (__| |_| | _ <| |___
* \___|\___/|_| \_\_____|
*
* Copyright (C) Daniel Stenberg, <daniel@haxx.se>, et al.
*
* This software is licensed as described in the file COPYING, which
* you should have received as part of this distribution. The terms
* are also available at https://curl.se/docs/copyright.html.
*
* You may opt to use, copy, modify, merge, publish, distribute and/or sell
* copies of the Software, and permit persons to whom the Software is
* furnished to do so, under the terms of the COPYING file.
*
* This software is distributed on an "AS IS" basis, WITHOUT WARRANTY OF ANY
* KIND, either express or implied.
*
* SPDX-License-Identifier: curl
*
***************************************************************************/
struct Curl_easy;
struct Curl_cfilter;
/**
* Init logging, return != 0 on failure.
*/
CURLcode Curl_trc_init(void);
/**
* Configure tracing. May be called several times during global
* initialization. Later calls may not take effect.
*
* Configuration format supported:
* - comma-separated list of component names to enable logging on.
* E.g. 'http/2,ssl'. Unkown names are ignored. Names are compared
* case-insensitive.
* - component 'all' applies to all known log components
* - prefixing a component with '+' or '-' will en-/disable logging for
* that component
* Example: 'all,-ssl' would enable logging for all components but the
* SSL filters.
*
* @param config configuration string
*/
CURLcode Curl_trc_opt(const char *config);
/* the function used to output verbose information */
void Curl_debug(struct Curl_easy *data, curl_infotype type,
char *ptr, size_t size);
/**
* Output an informational message when transfer's verbose logging is enabled.
*/
void Curl_infof(struct Curl_easy *data,
#if defined(__GNUC__) && !defined(printf) && \
defined(__STDC_VERSION__) && (__STDC_VERSION__ >= 199901L) && \
!defined(__MINGW32__)
const char *fmt, ...)
__attribute__((format(printf, 2, 3)));
#else
const char *fmt, ...);
#endif
/**
* Output a failure message on registered callbacks for transfer.
*/
void Curl_failf(struct Curl_easy *data,
#if defined(__GNUC__) && !defined(printf) && \
defined(__STDC_VERSION__) && (__STDC_VERSION__ >= 199901L) && \
!defined(__MINGW32__)
const char *fmt, ...)
__attribute__((format(printf, 2, 3)));
#else
const char *fmt, ...);
#endif
#define failf Curl_failf
/**
* Output an informational message when both transfer's verbose logging
* and connection filters verbose logging are enabled.
*/
void Curl_trc_cf_infof(struct Curl_easy *data, struct Curl_cfilter *cf,
#if defined(__GNUC__) && !defined(printf) && \
defined(__STDC_VERSION__) && (__STDC_VERSION__ >= 199901L) && \
!defined(__MINGW32__)
const char *fmt, ...)
__attribute__((format(printf, 3, 4)));
#else
const char *fmt, ...);
#endif
#define CURL_LOG_LVL_NONE 0
#define CURL_LOG_LVL_INFO 1
#if !defined(CURL_DISABLE_VERBOSE_STRINGS)
/* informational messages enabled */
#define Curl_trc_is_verbose(data) ((data) && (data)->set.verbose)
#define Curl_trc_cf_is_verbose(cf, data) \
((data) && (data)->set.verbose && \
(cf) && (cf)->cft->log_level >= CURL_LOG_LVL_INFO)
/* explainer: we have some mix configuration and werror settings
* that define HAVE_VARIADIC_MACROS_C99 even though C89 is enforced
* on gnuc and some other compiler. Need to treat carefully.
*/
#if defined(HAVE_VARIADIC_MACROS_C99) && \
defined(__STDC_VERSION__) && (__STDC_VERSION__ >= 199901L)
#define infof(data, ...) \
do { if(Curl_trc_is_verbose(data)) \
Curl_infof(data, __VA_ARGS__); } while(0)
#define CURL_TRC_CF(data, cf, ...) \
do { if(Curl_trc_cf_is_verbose(cf, data)) \
Curl_trc_cf_infof(data, cf, __VA_ARGS__); } while(0)
#else /* no variadic macro args */
#define infof Curl_infof
#define CURL_TRC_CF Curl_trc_cf_infof
#endif /* variadic macro args */
#else /* !CURL_DISABLE_VERBOSE_STRINGS */
/* All informational messages are not compiled in for size savings */
#define Curl_trc_is_verbose(d) ((void)(d), FALSE)
#define Curl_trc_cf_is_verbose(x,y) ((void)(x), (void)(y), FALSE)
#if defined(HAVE_VARIADIC_MACROS_C99)
#define infof(...) Curl_nop_stmt
#define CURL_TRC_CF(...) Curl_nop_stmt
#define Curl_trc_cf_infof(...) Curl_nop_stmt
#elif defined(HAVE_VARIADIC_MACROS_GCC)
#define infof(x...) Curl_nop_stmt
#define CURL_TRC_CF(x...) Curl_nop_stmt
#define Curl_trc_cf_infof(x...) Curl_nop_stmt
#else
#error "missing VARIADIC macro define, fix and rebuild!"
#endif
#endif /* CURL_DISABLE_VERBOSE_STRINGS */
#endif /* HEADER_CURL_TRC_H */

19
lib/easy.c
View File

@ -158,8 +158,8 @@ static CURLcode global_init(long flags, bool memoryfuncs)
#endif #endif
} }
if(Curl_log_init()) { if(Curl_trc_init()) {
DEBUGF(fprintf(stderr, "Error: Curl_log_init failed\n")); DEBUGF(fprintf(stderr, "Error: Curl_trc_init failed\n"));
goto fail; goto fail;
} }
@ -315,6 +315,21 @@ void curl_global_cleanup(void)
global_init_unlock(); global_init_unlock();
} }
/**
* curl_global_trace() globally initializes curl logging.
*/
CURLcode curl_global_trace(const char *config)
{
CURLcode result;
global_init_lock();
result = Curl_trc_opt(config);
global_init_unlock();
return result;
}
/* /*
* curl_global_sslset() globally initializes the SSL backend to use. * curl_global_sslset() globally initializes the SSL backend to use.
*/ */

199
lib/http2.c
View File

@ -217,8 +217,8 @@ static void drain_stream(struct Curl_cfilter *cf,
(stream->upload_left || stream->upload_blocked_len)) (stream->upload_left || stream->upload_blocked_len))
bits |= CURL_CSELECT_OUT; bits |= CURL_CSELECT_OUT;
if(data->state.dselect_bits != bits) { if(data->state.dselect_bits != bits) {
DEBUGF(LOG_CF(data, cf, "[h2sid=%d] DRAIN dselect_bits=%x", CURL_TRC_CF(data, cf, "[h2sid=%d] DRAIN dselect_bits=%x",
stream->id, bits)); stream->id, bits);
data->state.dselect_bits = bits; data->state.dselect_bits = bits;
Curl_expire(data, 0, EXPIRE_RUN_NOW); Curl_expire(data, 0, EXPIRE_RUN_NOW);
} }
@ -281,8 +281,8 @@ static void http2_data_done(struct Curl_cfilter *cf,
if(ctx->h2) { if(ctx->h2) {
if(!stream->closed && stream->id > 0) { if(!stream->closed && stream->id > 0) {
/* RST_STREAM */ /* RST_STREAM */
DEBUGF(LOG_CF(data, cf, "[h2sid=%d] premature DATA_DONE, RST stream", CURL_TRC_CF(data, cf, "[h2sid=%d] premature DATA_DONE, RST stream",
stream->id)); stream->id);
if(!nghttp2_submit_rst_stream(ctx->h2, NGHTTP2_FLAG_NONE, if(!nghttp2_submit_rst_stream(ctx->h2, NGHTTP2_FLAG_NONE,
stream->id, NGHTTP2_STREAM_CLOSED)) stream->id, NGHTTP2_STREAM_CLOSED))
(void)nghttp2_session_send(ctx->h2); (void)nghttp2_session_send(ctx->h2);
@ -535,8 +535,8 @@ static int h2_process_pending_input(struct Curl_cfilter *cf,
break; break;
} }
else { else {
DEBUGF(LOG_CF(data, cf, "process_pending_input: %zu bytes left " CURL_TRC_CF(data, cf, "process_pending_input: %zu bytes left "
"in connection buffer", Curl_bufq_len(&ctx->inbufq))); "in connection buffer", Curl_bufq_len(&ctx->inbufq));
} }
} }
@ -578,8 +578,8 @@ static bool http2_connisalive(struct Curl_cfilter *cf, struct Curl_easy *data,
*input_pending = FALSE; *input_pending = FALSE;
nread = Curl_bufq_slurp(&ctx->inbufq, nw_in_reader, cf, &result); nread = Curl_bufq_slurp(&ctx->inbufq, nw_in_reader, cf, &result);
if(nread != -1) { if(nread != -1) {
DEBUGF(LOG_CF(data, cf, "%zd bytes stray data read before trying " CURL_TRC_CF(data, cf, "%zd bytes stray data read before trying "
"h2 connection", nread)); "h2 connection", nread);
if(h2_process_pending_input(cf, data, &result) < 0) if(h2_process_pending_input(cf, data, &result) < 0)
/* immediate error, considered dead */ /* immediate error, considered dead */
alive = FALSE; alive = FALSE;
@ -641,13 +641,13 @@ static CURLcode nw_out_flush(struct Curl_cfilter *cf,
nwritten = Curl_bufq_pass(&ctx->outbufq, nw_out_writer, cf, &result); nwritten = Curl_bufq_pass(&ctx->outbufq, nw_out_writer, cf, &result);
if(nwritten < 0) { if(nwritten < 0) {
if(result == CURLE_AGAIN) { if(result == CURLE_AGAIN) {
DEBUGF(LOG_CF(data, cf, "flush nw send buffer(%zu) -> EAGAIN", CURL_TRC_CF(data, cf, "flush nw send buffer(%zu) -> EAGAIN",
Curl_bufq_len(&ctx->outbufq))); Curl_bufq_len(&ctx->outbufq));
ctx->nw_out_blocked = 1; ctx->nw_out_blocked = 1;
} }
return result; return result;
} }
DEBUGF(LOG_CF(data, cf, "nw send buffer flushed")); CURL_TRC_CF(data, cf, "nw send buffer flushed");
return Curl_bufq_is_empty(&ctx->outbufq)? CURLE_OK: CURLE_AGAIN; return Curl_bufq_is_empty(&ctx->outbufq)? CURLE_OK: CURLE_AGAIN;
} }
@ -839,8 +839,8 @@ static int push_promise(struct Curl_cfilter *cf,
struct cf_h2_ctx *ctx = cf->ctx; struct cf_h2_ctx *ctx = cf->ctx;
int rv; /* one of the CURL_PUSH_* defines */ int rv; /* one of the CURL_PUSH_* defines */
DEBUGF(LOG_CF(data, cf, "[h2sid=%d] PUSH_PROMISE received", CURL_TRC_CF(data, cf, "[h2sid=%d] PUSH_PROMISE received",
frame->promised_stream_id)); frame->promised_stream_id);
if(data->multi->push_cb) { if(data->multi->push_cb) {
struct stream_ctx *stream; struct stream_ctx *stream;
struct stream_ctx *newstream; struct stream_ctx *newstream;
@ -859,7 +859,7 @@ static int push_promise(struct Curl_cfilter *cf,
heads.data = data; heads.data = data;
heads.frame = frame; heads.frame = frame;
/* ask the application */ /* ask the application */
DEBUGF(LOG_CF(data, cf, "Got PUSH_PROMISE, ask application")); CURL_TRC_CF(data, cf, "Got PUSH_PROMISE, ask application");
stream = H2_STREAM_CTX(data); stream = H2_STREAM_CTX(data);
if(!stream) { if(!stream) {
@ -931,7 +931,7 @@ static int push_promise(struct Curl_cfilter *cf,
} }
} }
else { else {
DEBUGF(LOG_CF(data, cf, "Got PUSH_PROMISE, ignore it")); CURL_TRC_CF(data, cf, "Got PUSH_PROMISE, ignore it");
rv = CURL_PUSH_DENY; rv = CURL_PUSH_DENY;
} }
fail: fail:
@ -968,20 +968,20 @@ static CURLcode on_stream_frame(struct Curl_cfilter *cf,
int rv; int rv;
if(!stream) { if(!stream) {
DEBUGF(LOG_CF(data, cf, "[h2sid=%d] No proto pointer", stream_id)); CURL_TRC_CF(data, cf, "[h2sid=%d] No proto pointer", stream_id);
return CURLE_FAILED_INIT; return CURLE_FAILED_INIT;
} }
switch(frame->hd.type) { switch(frame->hd.type) {
case NGHTTP2_DATA: case NGHTTP2_DATA:
rbuflen = Curl_bufq_len(&stream->recvbuf); rbuflen = Curl_bufq_len(&stream->recvbuf);
DEBUGF(LOG_CF(data, cf, "[h2sid=%d] FRAME[DATA len=%zu pad=%zu], " CURL_TRC_CF(data, cf, "[h2sid=%d] FRAME[DATA len=%zu pad=%zu], "
"buffered=%zu, window=%d/%d", "buffered=%zu, window=%d/%d",
stream_id, frame->hd.length, frame->data.padlen, rbuflen, stream_id, frame->hd.length, frame->data.padlen, rbuflen,
nghttp2_session_get_stream_effective_recv_data_length( nghttp2_session_get_stream_effective_recv_data_length(
ctx->h2, stream->id), ctx->h2, stream->id),
nghttp2_session_get_stream_effective_local_window_size( nghttp2_session_get_stream_effective_local_window_size(
ctx->h2, stream->id))); ctx->h2, stream->id));
/* If !body started on this stream, then receiving DATA is illegal. */ /* If !body started on this stream, then receiving DATA is illegal. */
if(!stream->bodystarted) { if(!stream->bodystarted) {
rv = nghttp2_submit_rst_stream(ctx->h2, NGHTTP2_FLAG_NONE, rv = nghttp2_submit_rst_stream(ctx->h2, NGHTTP2_FLAG_NONE,
@ -1010,7 +1010,7 @@ static CURLcode on_stream_frame(struct Curl_cfilter *cf,
} }
break; break;
case NGHTTP2_HEADERS: case NGHTTP2_HEADERS:
DEBUGF(LOG_CF(data, cf, "[h2sid=%d] FRAME[HEADERS]", stream_id)); CURL_TRC_CF(data, cf, "[h2sid=%d] FRAME[HEADERS]", stream_id);
if(stream->bodystarted) { if(stream->bodystarted) {
/* Only valid HEADERS after body started is trailer HEADERS. We /* Only valid HEADERS after body started is trailer HEADERS. We
buffer them in on_header callback. */ buffer them in on_header callback. */
@ -1033,12 +1033,12 @@ static CURLcode on_stream_frame(struct Curl_cfilter *cf,
if(result) if(result)
return result; return result;
DEBUGF(LOG_CF(data, cf, "[h2sid=%d] %zu header bytes", CURL_TRC_CF(data, cf, "[h2sid=%d] %zu header bytes",
stream_id, Curl_bufq_len(&stream->recvbuf))); stream_id, Curl_bufq_len(&stream->recvbuf));
drain_stream(cf, data, stream); drain_stream(cf, data, stream);
break; break;
case NGHTTP2_PUSH_PROMISE: case NGHTTP2_PUSH_PROMISE:
DEBUGF(LOG_CF(data, cf, "[h2sid=%d] FRAME[PUSH_PROMISE]", stream_id)); CURL_TRC_CF(data, cf, "[h2sid=%d] FRAME[PUSH_PROMISE]", stream_id);
rv = push_promise(cf, data, &frame->push_promise); rv = push_promise(cf, data, &frame->push_promise);
if(rv) { /* deny! */ if(rv) { /* deny! */
DEBUGASSERT((rv > CURL_PUSH_OK) && (rv <= CURL_PUSH_ERROROUT)); DEBUGASSERT((rv > CURL_PUSH_OK) && (rv <= CURL_PUSH_ERROROUT));
@ -1048,14 +1048,14 @@ static CURLcode on_stream_frame(struct Curl_cfilter *cf,
if(nghttp2_is_fatal(rv)) if(nghttp2_is_fatal(rv))
return CURLE_SEND_ERROR; return CURLE_SEND_ERROR;
else if(rv == CURL_PUSH_ERROROUT) { else if(rv == CURL_PUSH_ERROROUT) {
DEBUGF(LOG_CF(data, cf, "[h2sid=%d] fail in PUSH_PROMISE received", CURL_TRC_CF(data, cf, "[h2sid=%d] fail in PUSH_PROMISE received",
stream_id)); stream_id);
return CURLE_RECV_ERROR; return CURLE_RECV_ERROR;
} }
} }
break; break;
case NGHTTP2_RST_STREAM: case NGHTTP2_RST_STREAM:
DEBUGF(LOG_CF(data, cf, "[h2sid=%d] FRAME[RST]", stream_id)); CURL_TRC_CF(data, cf, "[h2sid=%d] FRAME[RST]", stream_id);
stream->closed = TRUE; stream->closed = TRUE;
stream->reset = TRUE; stream->reset = TRUE;
stream->send_closed = TRUE; stream->send_closed = TRUE;
@ -1063,18 +1063,17 @@ static CURLcode on_stream_frame(struct Curl_cfilter *cf,
drain_stream(cf, data, stream); drain_stream(cf, data, stream);
break; break;
case NGHTTP2_WINDOW_UPDATE: case NGHTTP2_WINDOW_UPDATE:
DEBUGF(LOG_CF(data, cf, "[h2sid=%d] FRAME[WINDOW_UPDATE]", stream_id)); CURL_TRC_CF(data, cf, "[h2sid=%d] FRAME[WINDOW_UPDATE]", stream_id);
if((data->req.keepon & KEEP_SEND_HOLD) && if((data->req.keepon & KEEP_SEND_HOLD) &&
(data->req.keepon & KEEP_SEND)) { (data->req.keepon & KEEP_SEND)) {
data->req.keepon &= ~KEEP_SEND_HOLD; data->req.keepon &= ~KEEP_SEND_HOLD;
drain_stream(cf, data, stream); drain_stream(cf, data, stream);
DEBUGF(LOG_CF(data, cf, "[h2sid=%d] un-holding after win update", CURL_TRC_CF(data, cf, "[h2sid=%d] un-holding after win update",
stream_id)); stream_id);
} }
break; break;
default: default:
DEBUGF(LOG_CF(data, cf, "[h2sid=%d] FRAME[%x]", CURL_TRC_CF(data, cf, "[h2sid=%d] FRAME[%x]", stream_id, frame->hd.type);
stream_id, frame->hd.type));
break; break;
} }
return CURLE_OK; return CURLE_OK;
@ -1095,19 +1094,19 @@ static int on_frame_recv(nghttp2_session *session, const nghttp2_frame *frame,
switch(frame->hd.type) { switch(frame->hd.type) {
case NGHTTP2_SETTINGS: { case NGHTTP2_SETTINGS: {
uint32_t max_conn = ctx->max_concurrent_streams; uint32_t max_conn = ctx->max_concurrent_streams;
DEBUGF(LOG_CF(data, cf, "FRAME[SETTINGS]")); CURL_TRC_CF(data, cf, "FRAME[SETTINGS]");
ctx->max_concurrent_streams = nghttp2_session_get_remote_settings( ctx->max_concurrent_streams = nghttp2_session_get_remote_settings(
session, NGHTTP2_SETTINGS_MAX_CONCURRENT_STREAMS); session, NGHTTP2_SETTINGS_MAX_CONCURRENT_STREAMS);
ctx->enable_push = nghttp2_session_get_remote_settings( ctx->enable_push = nghttp2_session_get_remote_settings(
session, NGHTTP2_SETTINGS_ENABLE_PUSH) != 0; session, NGHTTP2_SETTINGS_ENABLE_PUSH) != 0;
DEBUGF(LOG_CF(data, cf, "MAX_CONCURRENT_STREAMS == %d", CURL_TRC_CF(data, cf, "MAX_CONCURRENT_STREAMS == %d",
ctx->max_concurrent_streams)); ctx->max_concurrent_streams);
DEBUGF(LOG_CF(data, cf, "ENABLE_PUSH == %s", CURL_TRC_CF(data, cf, "ENABLE_PUSH == %s",
ctx->enable_push ? "TRUE" : "false")); ctx->enable_push ? "TRUE" : "false");
if(data && max_conn != ctx->max_concurrent_streams) { if(data && max_conn != ctx->max_concurrent_streams) {
/* only signal change if the value actually changed */ /* only signal change if the value actually changed */
DEBUGF(LOG_CF(data, cf, "MAX_CONCURRENT_STREAMS now %u", CURL_TRC_CF(data, cf, "MAX_CONCURRENT_STREAMS now %u",
ctx->max_concurrent_streams)); ctx->max_concurrent_streams);
Curl_multi_connchanged(data->multi); Curl_multi_connchanged(data->multi);
} }
/* Since the initial stream window is 64K, a request might be on HOLD, /* Since the initial stream window is 64K, a request might be on HOLD,
@ -1121,8 +1120,8 @@ static int on_frame_recv(nghttp2_session *session, const nghttp2_frame *frame,
data->req.keepon &= ~KEEP_SEND_HOLD; data->req.keepon &= ~KEEP_SEND_HOLD;
if(stream) { if(stream) {
drain_stream(cf, data, stream); drain_stream(cf, data, stream);
DEBUGF(LOG_CF(data, cf, "[h2sid=%d] un-holding after SETTINGS", CURL_TRC_CF(data, cf, "[h2sid=%d] un-holding after SETTINGS",
stream_id)); stream_id);
} }
} }
break; break;
@ -1132,26 +1131,25 @@ static int on_frame_recv(nghttp2_session *session, const nghttp2_frame *frame,
ctx->goaway_error = frame->goaway.error_code; ctx->goaway_error = frame->goaway.error_code;
ctx->last_stream_id = frame->goaway.last_stream_id; ctx->last_stream_id = frame->goaway.last_stream_id;
if(data) { if(data) {
DEBUGF(LOG_CF(data, cf, "FRAME[GOAWAY, error=%d, last_stream=%u]", CURL_TRC_CF(data, cf, "FRAME[GOAWAY, error=%d, last_stream=%u]",
ctx->goaway_error, ctx->last_stream_id)); ctx->goaway_error, ctx->last_stream_id);
infof(data, "received GOAWAY, error=%d, last_stream=%u", infof(data, "received GOAWAY, error=%d, last_stream=%u",
ctx->goaway_error, ctx->last_stream_id); ctx->goaway_error, ctx->last_stream_id);
Curl_multi_connchanged(data->multi); Curl_multi_connchanged(data->multi);
} }
break; break;
case NGHTTP2_WINDOW_UPDATE: case NGHTTP2_WINDOW_UPDATE:
DEBUGF(LOG_CF(data, cf, "FRAME[WINDOW_UPDATE]")); CURL_TRC_CF(data, cf, "FRAME[WINDOW_UPDATE]");
break; break;
default: default:
DEBUGF(LOG_CF(data, cf, "recv frame %x on 0", frame->hd.type)); CURL_TRC_CF(data, cf, "recv frame %x on 0", frame->hd.type);
} }
return 0; return 0;
} }
data_s = nghttp2_session_get_stream_user_data(session, stream_id); data_s = nghttp2_session_get_stream_user_data(session, stream_id);
if(!data_s) { if(!data_s) {
DEBUGF(LOG_CF(data, cf, "[h2sid=%d] No Curl_easy associated", CURL_TRC_CF(data, cf, "[h2sid=%d] No Curl_easy associated", stream_id);
stream_id));
return 0; return 0;
} }
@ -1178,8 +1176,8 @@ static int on_data_chunk_recv(nghttp2_session *session, uint8_t flags,
/* Receiving a Stream ID not in the hash should not happen - unless /* Receiving a Stream ID not in the hash should not happen - unless
we have aborted a transfer artificially and there were more data we have aborted a transfer artificially and there were more data
in the pipeline. Silently ignore. */ in the pipeline. Silently ignore. */
DEBUGF(LOG_CF(CF_DATA_CURRENT(cf), cf, "[h2sid=%d] Data for unknown", CURL_TRC_CF(CF_DATA_CURRENT(cf), cf, "[h2sid=%d] Data for unknown",
stream_id)); stream_id);
/* consumed explicitly as no one will read it */ /* consumed explicitly as no one will read it */
nghttp2_session_consume(session, stream_id, len); nghttp2_session_consume(session, stream_id, len);
return 0; return 0;
@ -1221,8 +1219,8 @@ static int on_stream_close(nghttp2_session *session, int32_t stream_id,
return 0; return 0;
} }
stream = H2_STREAM_CTX(data_s); stream = H2_STREAM_CTX(data_s);
DEBUGF(LOG_CF(data_s, cf, "[h2sid=%d] on_stream_close(), %s (err %d)", CURL_TRC_CF(data_s, cf, "[h2sid=%d] on_stream_close(), %s (err %d)",
stream_id, nghttp2_http2_strerror(error_code), error_code)); stream_id, nghttp2_http2_strerror(error_code), error_code);
if(!stream) if(!stream)
return NGHTTP2_ERR_CALLBACK_FAILURE; return NGHTTP2_ERR_CALLBACK_FAILURE;
@ -1241,7 +1239,7 @@ static int on_stream_close(nghttp2_session *session, int32_t stream_id,
stream_id); stream_id);
DEBUGASSERT(0); DEBUGASSERT(0);
} }
DEBUGF(LOG_CF(data_s, cf, "[h2sid=%d] closed now", stream_id)); CURL_TRC_CF(data_s, cf, "[h2sid=%d] closed now", stream_id);
return 0; return 0;
} }
@ -1258,7 +1256,7 @@ static int on_begin_headers(nghttp2_session *session,
return 0; return 0;
} }
DEBUGF(LOG_CF(data_s, cf, "on_begin_headers() was called")); CURL_TRC_CF(data_s, cf, "on_begin_headers() was called");
if(frame->hd.type != NGHTTP2_HEADERS) { if(frame->hd.type != NGHTTP2_HEADERS) {
return 0; return 0;
@ -1365,10 +1363,8 @@ static int on_header(nghttp2_session *session, const nghttp2_frame *frame,
if(stream->bodystarted) { if(stream->bodystarted) {
/* This is a trailer */ /* This is a trailer */
DEBUGF(LOG_CF(data_s, cf, "[h2sid=%d] trailer: %.*s: %.*s", CURL_TRC_CF(data_s, cf, "[h2sid=%d] trailer: %.*s: %.*s",
stream->id, stream->id, (int)namelen, name, (int)valuelen, value);
(int)namelen, name,
(int)valuelen, value));
result = Curl_dynhds_add(&stream->resp_trailers, result = Curl_dynhds_add(&stream->resp_trailers,
(const char *)name, namelen, (const char *)name, namelen,
(const char *)value, valuelen); (const char *)value, valuelen);
@ -1405,8 +1401,8 @@ static int on_header(nghttp2_session *session, const nghttp2_frame *frame,
if(CF_DATA_CURRENT(cf) != data_s) if(CF_DATA_CURRENT(cf) != data_s)
Curl_expire(data_s, 0, EXPIRE_RUN_NOW); Curl_expire(data_s, 0, EXPIRE_RUN_NOW);
DEBUGF(LOG_CF(data_s, cf, "[h2sid=%d] status: HTTP/2 %03d", CURL_TRC_CF(data_s, cf, "[h2sid=%d] status: HTTP/2 %03d",
stream->id, stream->status_code)); stream->id, stream->status_code);
return 0; return 0;
} }
@ -1429,10 +1425,8 @@ static int on_header(nghttp2_session *session, const nghttp2_frame *frame,
if(CF_DATA_CURRENT(cf) != data_s) if(CF_DATA_CURRENT(cf) != data_s)
Curl_expire(data_s, 0, EXPIRE_RUN_NOW); Curl_expire(data_s, 0, EXPIRE_RUN_NOW);
DEBUGF(LOG_CF(data_s, cf, "[h2sid=%d] header: %.*s: %.*s", CURL_TRC_CF(data_s, cf, "[h2sid=%d] header: %.*s: %.*s",
stream->id, stream->id, (int)namelen, name, (int)valuelen, value);
(int)namelen, name,
(int)valuelen, value));
return 0; /* 0 is successful */ return 0; /* 0 is successful */
} }
@ -1478,9 +1472,9 @@ static ssize_t req_body_read_callback(nghttp2_session *session,
if(nread > 0 && stream->upload_left != -1) if(nread > 0 && stream->upload_left != -1)
stream->upload_left -= nread; stream->upload_left -= nread;
DEBUGF(LOG_CF(data_s, cf, "[h2sid=%d] req_body_read(len=%zu) left=%" CURL_TRC_CF(data_s, cf, "[h2sid=%d] req_body_read(len=%zu) left=%"
CURL_FORMAT_CURL_OFF_T " -> %zd, %d", CURL_FORMAT_CURL_OFF_T " -> %zd, %d",
stream_id, length, stream->upload_left, nread, result)); stream_id, length, stream->upload_left, nread, result);
if(stream->upload_left == 0) if(stream->upload_left == 0)
*data_flags = NGHTTP2_DATA_FLAG_EOF; *data_flags = NGHTTP2_DATA_FLAG_EOF;
@ -1553,7 +1547,7 @@ static CURLcode http2_data_done_send(struct Curl_cfilter *cf,
if(!ctx || !ctx->h2 || !stream) if(!ctx || !ctx->h2 || !stream)
goto out; goto out;
DEBUGF(LOG_CF(data, cf, "[h2sid=%d] data done send", stream->id)); CURL_TRC_CF(data, cf, "[h2sid=%d] data done send", stream->id);
if(!stream->send_closed) { if(!stream->send_closed) {
stream->send_closed = TRUE; stream->send_closed = TRUE;
if(stream->upload_left) { if(stream->upload_left) {
@ -1578,8 +1572,8 @@ static ssize_t http2_handle_stream_close(struct Curl_cfilter *cf,
ssize_t rv = 0; ssize_t rv = 0;
if(stream->error == NGHTTP2_REFUSED_STREAM) { if(stream->error == NGHTTP2_REFUSED_STREAM) {
DEBUGF(LOG_CF(data, cf, "[h2sid=%d] REFUSED_STREAM, try again on a new " CURL_TRC_CF(data, cf, "[h2sid=%d] REFUSED_STREAM, try again on a new "
"connection", stream->id)); "connection", stream->id);
connclose(cf->conn, "REFUSED_STREAM"); /* don't use this anymore */ connclose(cf->conn, "REFUSED_STREAM"); /* don't use this anymore */
data->state.refused_stream = TRUE; data->state.refused_stream = TRUE;
*err = CURLE_SEND_ERROR; /* trigger Curl_retry_request() later */ *err = CURLE_SEND_ERROR; /* trigger Curl_retry_request() later */
@ -1640,7 +1634,7 @@ static ssize_t http2_handle_stream_close(struct Curl_cfilter *cf,
rv = 0; rv = 0;
out: out:
DEBUGF(LOG_CF(data, cf, "handle_stream_close -> %zd, %d", rv, *err)); CURL_TRC_CF(data, cf, "handle_stream_close -> %zd, %d", rv, *err);
return rv; return rv;
} }
@ -1697,8 +1691,7 @@ static CURLcode h2_progress_egress(struct Curl_cfilter *cf,
nghttp2_priority_spec pri_spec; nghttp2_priority_spec pri_spec;
h2_pri_spec(data, &pri_spec); h2_pri_spec(data, &pri_spec);
DEBUGF(LOG_CF(data, cf, "[h2sid=%d] Queuing PRIORITY", CURL_TRC_CF(data, cf, "[h2sid=%d] Queuing PRIORITY", stream->id);
stream->id));
DEBUGASSERT(stream->id != -1); DEBUGASSERT(stream->id != -1);
rv = nghttp2_submit_priority(ctx->h2, NGHTTP2_FLAG_NONE, rv = nghttp2_submit_priority(ctx->h2, NGHTTP2_FLAG_NONE,
stream->id, &pri_spec); stream->id, &pri_spec);
@ -1712,8 +1705,8 @@ static CURLcode h2_progress_egress(struct Curl_cfilter *cf,
out: out:
if(nghttp2_is_fatal(rv)) { if(nghttp2_is_fatal(rv)) {
DEBUGF(LOG_CF(data, cf, "nghttp2_session_send error (%s)%d", CURL_TRC_CF(data, cf, "nghttp2_session_send error (%s)%d",
nghttp2_strerror(rv), rv)); nghttp2_strerror(rv), rv);
return CURLE_SEND_ERROR; return CURLE_SEND_ERROR;
} }
return nw_out_flush(cf, data); return nw_out_flush(cf, data);
@ -1730,8 +1723,8 @@ static ssize_t stream_recv(struct Curl_cfilter *cf, struct Curl_easy *data,
if(!Curl_bufq_is_empty(&stream->recvbuf)) { if(!Curl_bufq_is_empty(&stream->recvbuf)) {
nread = Curl_bufq_read(&stream->recvbuf, nread = Curl_bufq_read(&stream->recvbuf,
(unsigned char *)buf, len, err); (unsigned char *)buf, len, err);
DEBUGF(LOG_CF(data, cf, "recvbuf read(len=%zu) -> %zd, %d", CURL_TRC_CF(data, cf, "recvbuf read(len=%zu) -> %zd, %d",
len, nread, *err)); len, nread, *err);
if(nread < 0) if(nread < 0)
goto out; goto out;
DEBUGASSERT(nread > 0); DEBUGASSERT(nread > 0);
@ -1739,13 +1732,13 @@ static ssize_t stream_recv(struct Curl_cfilter *cf, struct Curl_easy *data,
if(nread < 0) { if(nread < 0) {
if(stream->closed) { if(stream->closed) {
DEBUGF(LOG_CF(data, cf, "[h2sid=%d] returning CLOSE", stream->id)); CURL_TRC_CF(data, cf, "[h2sid=%d] returning CLOSE", stream->id);
nread = http2_handle_stream_close(cf, data, stream, err); nread = http2_handle_stream_close(cf, data, stream, err);
} }
else if(stream->reset || else if(stream->reset ||
(ctx->conn_closed && Curl_bufq_is_empty(&ctx->inbufq)) || (ctx->conn_closed && Curl_bufq_is_empty(&ctx->inbufq)) ||
(ctx->goaway && ctx->last_stream_id < stream->id)) { (ctx->goaway && ctx->last_stream_id < stream->id)) {
DEBUGF(LOG_CF(data, cf, "[h2sid=%d] returning ERR", stream->id)); CURL_TRC_CF(data, cf, "[h2sid=%d] returning ERR", stream->id);
*err = stream->bodystarted? CURLE_PARTIAL_FILE : CURLE_RECV_ERROR; *err = stream->bodystarted? CURLE_PARTIAL_FILE : CURLE_RECV_ERROR;
nread = -1; nread = -1;
} }
@ -1756,8 +1749,7 @@ static ssize_t stream_recv(struct Curl_cfilter *cf, struct Curl_easy *data,
} }
out: out:
DEBUGF(LOG_CF(data, cf, "stream_recv(len=%zu) -> %zd, %d", CURL_TRC_CF(data, cf, "stream_recv(len=%zu) -> %zd, %d", len, nread, *err);
len, nread, *err));
return nread; return nread;
} }
@ -1771,8 +1763,8 @@ static CURLcode h2_progress_ingress(struct Curl_cfilter *cf,
/* Process network input buffer fist */ /* Process network input buffer fist */
if(!Curl_bufq_is_empty(&ctx->inbufq)) { if(!Curl_bufq_is_empty(&ctx->inbufq)) {
DEBUGF(LOG_CF(data, cf, "Process %zu bytes in connection buffer", CURL_TRC_CF(data, cf, "Process %zu bytes in connection buffer",
Curl_bufq_len(&ctx->inbufq))); Curl_bufq_len(&ctx->inbufq));
if(h2_process_pending_input(cf, data, &result) < 0) if(h2_process_pending_input(cf, data, &result) < 0)
return result; return result;
} }
@ -1792,8 +1784,6 @@ static CURLcode h2_progress_ingress(struct Curl_cfilter *cf,
} }
nread = Curl_bufq_slurp(&ctx->inbufq, nw_in_reader, cf, &result); nread = Curl_bufq_slurp(&ctx->inbufq, nw_in_reader, cf, &result);
/* DEBUGF(LOG_CF(data, cf, "read %zu bytes nw data -> %zd, %d",
Curl_bufq_len(&ctx->inbufq), nread, result)); */
if(nread < 0) { if(nread < 0) {
if(result != CURLE_AGAIN) { if(result != CURLE_AGAIN) {
failf(data, "Failed receiving HTTP2 data: %d(%s)", result, failf(data, "Failed receiving HTTP2 data: %d(%s)", result,
@ -1872,8 +1862,7 @@ static ssize_t cf_h2_recv(struct Curl_cfilter *cf, struct Curl_easy *data,
} }
if(stream->closed) { if(stream->closed) {
DEBUGF(LOG_CF(data, cf, "[h2sid=%d] closed stream, set drain", CURL_TRC_CF(data, cf, "[h2sid=%d] closed stream, set drain", stream->id);
stream->id));
drain_stream(cf, data, stream); drain_stream(cf, data, stream);
} }
} }
@ -1884,7 +1873,7 @@ out:
*err = result; *err = result;
nread = -1; nread = -1;
} }
DEBUGF(LOG_CF(data, cf, "[h2sid=%d] cf_recv(len=%zu) -> %zd %d, " CURL_TRC_CF(data, cf, "[h2sid=%d] cf_recv(len=%zu) -> %zd %d, "
"buffered=%zu, window=%d/%d, connection %d/%d", "buffered=%zu, window=%d/%d, connection %d/%d",
stream->id, len, nread, *err, stream->id, len, nread, *err,
Curl_bufq_len(&stream->recvbuf), Curl_bufq_len(&stream->recvbuf),
@ -1893,7 +1882,7 @@ out:
nghttp2_session_get_stream_effective_local_window_size( nghttp2_session_get_stream_effective_local_window_size(
ctx->h2, stream->id), ctx->h2, stream->id),
nghttp2_session_get_local_window_size(ctx->h2), nghttp2_session_get_local_window_size(ctx->h2),
HTTP2_HUGE_WINDOW_SIZE)); HTTP2_HUGE_WINDOW_SIZE);
CF_DATA_RESTORE(cf, save); CF_DATA_RESTORE(cf, save);
return nread; return nread;
@ -1974,8 +1963,8 @@ static ssize_t h2_submit(struct stream_ctx **pstream,
h2_pri_spec(data, &pri_spec); h2_pri_spec(data, &pri_spec);
DEBUGF(LOG_CF(data, cf, "send request allowed %d", CURL_TRC_CF(data, cf, "send request allowed %d",
nghttp2_session_check_request_allowed(ctx->h2))); nghttp2_session_check_request_allowed(ctx->h2));
switch(data->state.httpreq) { switch(data->state.httpreq) {
case HTTPREQ_POST: case HTTPREQ_POST:
@ -2002,15 +1991,15 @@ static ssize_t h2_submit(struct stream_ctx **pstream,
Curl_safefree(nva); Curl_safefree(nva);
if(stream_id < 0) { if(stream_id < 0) {
DEBUGF(LOG_CF(data, cf, "send: nghttp2_submit_request error (%s)%u", CURL_TRC_CF(data, cf, "send: nghttp2_submit_request error (%s)%u",
nghttp2_strerror(stream_id), stream_id)); nghttp2_strerror(stream_id), stream_id);
*err = CURLE_SEND_ERROR; *err = CURLE_SEND_ERROR;
nwritten = -1; nwritten = -1;
goto out; goto out;
} }
DEBUGF(LOG_CF(data, cf, "[h2sid=%d] cf_send(len=%zu) submit %s", CURL_TRC_CF(data, cf, "[h2sid=%d] cf_send(len=%zu) submit %s",
stream_id, len, data->state.url)); stream_id, len, data->state.url);
infof(data, "Using Stream ID: %u", stream_id); infof(data, "Using Stream ID: %u", stream_id);
stream->id = stream_id; stream->id = stream_id;
stream->local_window_size = H2_STREAM_WINDOW_SIZE; stream->local_window_size = H2_STREAM_WINDOW_SIZE;
@ -2042,8 +2031,8 @@ static ssize_t h2_submit(struct stream_ctx **pstream,
} }
out: out:
DEBUGF(LOG_CF(data, cf, "[h2sid=%d] submit -> %zd, %d", CURL_TRC_CF(data, cf, "[h2sid=%d] submit -> %zd, %d",
stream? stream->id : -1, nwritten, *err)); stream? stream->id : -1, nwritten, *err);
*pstream = stream; *pstream = stream;
Curl_h1_req_parse_free(&h1); Curl_h1_req_parse_free(&h1);
Curl_dynhds_free(&h2_headers); Curl_dynhds_free(&h2_headers);
@ -2155,19 +2144,19 @@ 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 /* H2 flow window exhaustion. We need to HOLD upload until we get
* a WINDOW_UPDATE from the server. */ * a WINDOW_UPDATE from the server. */
data->req.keepon |= KEEP_SEND_HOLD; data->req.keepon |= KEEP_SEND_HOLD;
DEBUGF(LOG_CF(data, cf, "[h2sid=%d] holding send as remote flow " CURL_TRC_CF(data, cf, "[h2sid=%d] holding send as remote flow "
"window is exhausted", stream->id)); "window is exhausted", stream->id);
} }
/* Whatever the cause, we need to return CURL_EAGAIN for this call. /* Whatever the cause, we need to return CURL_EAGAIN for this call.
* We have unwritten state that needs us being invoked again and EAGAIN * We have unwritten state that needs us being invoked again and EAGAIN
* is the only way to ensure that. */ * is the only way to ensure that. */
stream->upload_blocked_len = nwritten; stream->upload_blocked_len = nwritten;
DEBUGF(LOG_CF(data, cf, "[h2sid=%d] cf_send(len=%zu) BLOCK: win %u/%zu " CURL_TRC_CF(data, cf, "[h2sid=%d] cf_send(len=%zu) BLOCK: win %u/%zu "
"blocked_len=%zu", "blocked_len=%zu",
stream->id, len, stream->id, len,
nghttp2_session_get_remote_window_size(ctx->h2), rwin, nghttp2_session_get_remote_window_size(ctx->h2), rwin,
nwritten)); nwritten);
*err = CURLE_AGAIN; *err = CURLE_AGAIN;
nwritten = -1; nwritten = -1;
goto out; goto out;
@ -2179,7 +2168,7 @@ static ssize_t cf_h2_send(struct Curl_cfilter *cf, struct Curl_easy *data,
nwritten = http2_handle_stream_close(cf, data, stream, err); nwritten = http2_handle_stream_close(cf, data, stream, err);
} }
else { else {
DEBUGF(LOG_CF(data, cf, "send: nothing to do in this session")); CURL_TRC_CF(data, cf, "send: nothing to do in this session");
*err = CURLE_HTTP2; *err = CURLE_HTTP2;
nwritten = -1; nwritten = -1;
} }
@ -2187,7 +2176,7 @@ static ssize_t cf_h2_send(struct Curl_cfilter *cf, struct Curl_easy *data,
out: out:
if(stream) { if(stream) {
DEBUGF(LOG_CF(data, cf, "[h2sid=%d] cf_send(len=%zu) -> %zd, %d, " CURL_TRC_CF(data, cf, "[h2sid=%d] cf_send(len=%zu) -> %zd, %d, "
"upload_left=%" CURL_FORMAT_CURL_OFF_T ", " "upload_left=%" CURL_FORMAT_CURL_OFF_T ", "
"h2 windows %d-%d (stream-conn), " "h2 windows %d-%d (stream-conn), "
"buffers %zu-%zu (stream-conn)", "buffers %zu-%zu (stream-conn)",
@ -2197,14 +2186,14 @@ out:
ctx->h2, stream->id), ctx->h2, stream->id),
nghttp2_session_get_remote_window_size(ctx->h2), nghttp2_session_get_remote_window_size(ctx->h2),
Curl_bufq_len(&stream->sendbuf), Curl_bufq_len(&stream->sendbuf),
Curl_bufq_len(&ctx->outbufq))); Curl_bufq_len(&ctx->outbufq));
} }
else { else {
DEBUGF(LOG_CF(data, cf, "cf_send(len=%zu) -> %zd, %d, " CURL_TRC_CF(data, cf, "cf_send(len=%zu) -> %zd, %d, "
"connection-window=%d, nw_send_buffer(%zu)", "connection-window=%d, nw_send_buffer(%zu)",
len, nwritten, *err, len, nwritten, *err,
nghttp2_session_get_remote_window_size(ctx->h2), nghttp2_session_get_remote_window_size(ctx->h2),
Curl_bufq_len(&ctx->outbufq))); Curl_bufq_len(&ctx->outbufq));
} }
CF_DATA_RESTORE(cf, save); CF_DATA_RESTORE(cf, save);
return nwritten; return nwritten;
@ -2421,8 +2410,8 @@ static bool cf_h2_is_alive(struct Curl_cfilter *cf,
CF_DATA_SAVE(save, cf, data); CF_DATA_SAVE(save, cf, data);
result = (ctx && ctx->h2 && http2_connisalive(cf, data, input_pending)); result = (ctx && ctx->h2 && http2_connisalive(cf, data, input_pending));
DEBUGF(LOG_CF(data, cf, "conn alive -> %d, input_pending=%d", CURL_TRC_CF(data, cf, "conn alive -> %d, input_pending=%d",
result, *input_pending)); result, *input_pending);
CF_DATA_RESTORE(cf, save); CF_DATA_RESTORE(cf, save);
return result; return result;
} }
@ -2473,7 +2462,7 @@ static CURLcode cf_h2_query(struct Curl_cfilter *cf,
struct Curl_cftype Curl_cft_nghttp2 = { struct Curl_cftype Curl_cft_nghttp2 = {
"HTTP/2", "HTTP/2",
CF_TYPE_MULTIPLEX, CF_TYPE_MULTIPLEX,
CURL_LOG_DEFAULT, CURL_LOG_LVL_NONE,
cf_h2_destroy, cf_h2_destroy,
cf_h2_connect, cf_h2_connect,
cf_h2_close, cf_h2_close,

12
lib/http_proxy.c
View File

@ -69,7 +69,7 @@ static CURLcode http_proxy_cf_connect(struct Curl_cfilter *cf,
return CURLE_OK; return CURLE_OK;
} }
DEBUGF(LOG_CF(data, cf, "connect")); CURL_TRC_CF(data, cf, "connect");
connect_sub: connect_sub:
result = cf->next->cft->do_connect(cf->next, data, blocking, done); result = cf->next->cft->do_connect(cf->next, data, blocking, done);
if(result || !*done) if(result || !*done)
@ -86,7 +86,7 @@ connect_sub:
case CURL_HTTP_VERSION_NONE: case CURL_HTTP_VERSION_NONE:
case CURL_HTTP_VERSION_1_0: case CURL_HTTP_VERSION_1_0:
case CURL_HTTP_VERSION_1_1: case CURL_HTTP_VERSION_1_1:
DEBUGF(LOG_CF(data, cf, "installing subfilter for HTTP/1.1")); CURL_TRC_CF(data, cf, "installing subfilter for HTTP/1.1");
infof(data, "CONNECT tunnel: HTTP/1.%d negotiated", infof(data, "CONNECT tunnel: HTTP/1.%d negotiated",
(alpn == CURL_HTTP_VERSION_1_0)? 0 : 1); (alpn == CURL_HTTP_VERSION_1_0)? 0 : 1);
result = Curl_cf_h1_proxy_insert_after(cf, data); result = Curl_cf_h1_proxy_insert_after(cf, data);
@ -96,7 +96,7 @@ connect_sub:
break; break;
#ifdef USE_NGHTTP2 #ifdef USE_NGHTTP2
case CURL_HTTP_VERSION_2: case CURL_HTTP_VERSION_2:
DEBUGF(LOG_CF(data, cf, "installing subfilter for HTTP/2")); CURL_TRC_CF(data, cf, "installing subfilter for HTTP/2");
infof(data, "CONNECT tunnel: HTTP/2 negotiated"); infof(data, "CONNECT tunnel: HTTP/2 negotiated");
result = Curl_cf_h2_proxy_insert_after(cf, data); result = Curl_cf_h2_proxy_insert_after(cf, data);
if(result) if(result)
@ -105,7 +105,7 @@ connect_sub:
break; break;
#endif #endif
default: default:
DEBUGF(LOG_CF(data, cf, "installing subfilter for default HTTP/1.1")); CURL_TRC_CF(data, cf, "installing subfilter for default HTTP/1.1");
infof(data, "CONNECT tunnel: unsupported ALPN(%d) negotiated", alpn); infof(data, "CONNECT tunnel: unsupported ALPN(%d) negotiated", alpn);
result = CURLE_COULDNT_CONNECT; result = CURLE_COULDNT_CONNECT;
goto out; goto out;
@ -156,7 +156,7 @@ static void http_proxy_cf_destroy(struct Curl_cfilter *cf,
struct cf_proxy_ctx *ctx = cf->ctx; struct cf_proxy_ctx *ctx = cf->ctx;
(void)data; (void)data;
DEBUGF(LOG_CF(data, cf, "destroy")); CURL_TRC_CF(data, cf, "destroy");
free(ctx); free(ctx);
} }
@ -165,7 +165,7 @@ static void http_proxy_cf_close(struct Curl_cfilter *cf,
{ {
struct cf_proxy_ctx *ctx = cf->ctx; struct cf_proxy_ctx *ctx = cf->ctx;
DEBUGF(LOG_CF(data, cf, "close")); CURL_TRC_CF(data, cf, "close");
cf->connected = FALSE; cf->connected = FALSE;
if(ctx->cf_protocol) { if(ctx->cf_protocol) {
struct Curl_cfilter *f; struct Curl_cfilter *f;

1
lib/rand.c
View File

@ -36,6 +36,7 @@ uint32_t arc4random(void);
#endif #endif
#include <curl/curl.h> #include <curl/curl.h>
#include "urldata.h"
#include "vtls/vtls.h" #include "vtls/vtls.h"
#include "sendf.h" #include "sendf.h"
#include "timeval.h" #include "timeval.h"

2
lib/sendf.h
View File

@ -26,7 +26,7 @@
#include "curl_setup.h" #include "curl_setup.h"
#include "curl_log.h" #include "curl_trc.h"
#define CLIENTWRITE_BODY (1<<0) #define CLIENTWRITE_BODY (1<<0)

8
lib/url.c
View File

@ -1494,13 +1494,7 @@ void Curl_verboseconnect(struct Curl_easy *data,
{ {
if(data->set.verbose) if(data->set.verbose)
infof(data, "Connected to %s (%s) port %u", infof(data, "Connected to %s (%s) port %u",
#ifndef CURL_DISABLE_PROXY CURL_CONN_HOST_DISPNAME(conn), conn->primary_ip, conn->port);
conn->bits.socksproxy ? conn->socks_proxy.host.dispname :
conn->bits.httpproxy ? conn->http_proxy.host.dispname :
#endif
conn->bits.conn_to_host ? conn->conn_to_host.dispname :
conn->host.dispname,
conn->primary_ip, conn->port);
} }
#endif #endif

12
lib/urldata.h
View File

@ -1076,6 +1076,18 @@ struct connectdata {
unsigned char gssapi_delegation; /* inherited from set.gssapi_delegation */ unsigned char gssapi_delegation; /* inherited from set.gssapi_delegation */
}; };
#ifndef CURL_DISABLE_PROXY
#define CURL_CONN_HOST_DISPNAME(c) \
((c)->bits.socksproxy ? (c)->socks_proxy.host.dispname : \
(c)->bits.httpproxy ? (c)->http_proxy.host.dispname : \
(c)->bits.conn_to_host ? (c)->conn_to_host.dispname : \
(c)->host.dispname)
#else
#define CURL_CONN_HOST_DISPNAME(c) \
(c)->bits.conn_to_host ? (c)->conn_to_host.dispname : \
(c)->host.dispname)
#endif
/* The end of connectdata. */ /* The end of connectdata. */
/* /*

64
lib/vquic/curl_msh3.c
View File

@ -30,7 +30,7 @@
#include "timeval.h" #include "timeval.h"
#include "multiif.h" #include "multiif.h"
#include "sendf.h" #include "sendf.h"
#include "curl_log.h" #include "curl_trc.h"
#include "cfilters.h" #include "cfilters.h"
#include "cf-socket.h" #include "cf-socket.h"
#include "connect.h" #include "connect.h"
@ -173,7 +173,7 @@ static CURLcode h3_data_setup(struct Curl_cfilter *cf,
msh3_lock_initialize(&stream->recv_lock); msh3_lock_initialize(&stream->recv_lock);
Curl_bufq_init2(&stream->recvbuf, H3_STREAM_CHUNK_SIZE, Curl_bufq_init2(&stream->recvbuf, H3_STREAM_CHUNK_SIZE,
H3_STREAM_RECV_CHUNKS, BUFQ_OPT_SOFT_LIMIT); H3_STREAM_RECV_CHUNKS, BUFQ_OPT_SOFT_LIMIT);
DEBUGF(LOG_CF(data, cf, "data setup")); CURL_TRC_CF(data, cf, "data setup");
return CURLE_OK; return CURLE_OK;
} }
@ -183,7 +183,7 @@ static void h3_data_done(struct Curl_cfilter *cf, struct Curl_easy *data)
(void)cf; (void)cf;
if(stream) { if(stream) {
DEBUGF(LOG_CF(data, cf, "easy handle is done")); CURL_TRC_CF(data, cf, "easy handle is done");
Curl_bufq_free(&stream->recvbuf); Curl_bufq_free(&stream->recvbuf);
free(stream); free(stream);
H3_STREAM_LCTX(data) = NULL; H3_STREAM_LCTX(data) = NULL;
@ -235,7 +235,7 @@ static void MSH3_CALL msh3_conn_connected(MSH3_CONNECTION *Connection,
struct Curl_easy *data = CF_DATA_CURRENT(cf); struct Curl_easy *data = CF_DATA_CURRENT(cf);
(void)Connection; (void)Connection;
DEBUGF(LOG_CF(data, cf, "[MSH3] connected")); CURL_TRC_CF(data, cf, "[MSH3] connected");
ctx->handshake_succeeded = true; ctx->handshake_succeeded = true;
ctx->connected = true; ctx->connected = true;
ctx->handshake_complete = true; ctx->handshake_complete = true;
@ -249,7 +249,7 @@ static void MSH3_CALL msh3_conn_shutdown_complete(MSH3_CONNECTION *Connection,
struct Curl_easy *data = CF_DATA_CURRENT(cf); struct Curl_easy *data = CF_DATA_CURRENT(cf);
(void)Connection; (void)Connection;
DEBUGF(LOG_CF(data, cf, "[MSH3] shutdown complete")); CURL_TRC_CF(data, cf, "[MSH3] shutdown complete");
ctx->connected = false; ctx->connected = false;
ctx->handshake_complete = true; ctx->handshake_complete = true;
} }
@ -474,18 +474,18 @@ static ssize_t recv_closed_stream(struct Curl_cfilter *cf,
if(stream->reset) { if(stream->reset) {
failf(data, "HTTP/3 stream reset by server"); failf(data, "HTTP/3 stream reset by server");
*err = CURLE_PARTIAL_FILE; *err = CURLE_PARTIAL_FILE;
DEBUGF(LOG_CF(data, cf, "cf_recv, was reset -> %d", *err)); CURL_TRC_CF(data, cf, "cf_recv, was reset -> %d", *err);
goto out; goto out;
} }
else if(stream->error3) { else if(stream->error3) {
failf(data, "HTTP/3 stream was not closed cleanly: (error %zd)", failf(data, "HTTP/3 stream was not closed cleanly: (error %zd)",
(ssize_t)stream->error3); (ssize_t)stream->error3);
*err = CURLE_HTTP3; *err = CURLE_HTTP3;
DEBUGF(LOG_CF(data, cf, "cf_recv, closed uncleanly -> %d", *err)); CURL_TRC_CF(data, cf, "cf_recv, closed uncleanly -> %d", *err);
goto out; goto out;
} }
else { else {
DEBUGF(LOG_CF(data, cf, "cf_recv, closed ok -> %d", *err)); CURL_TRC_CF(data, cf, "cf_recv, closed ok -> %d", *err);
} }
*err = CURLE_OK; *err = CURLE_OK;
nread = 0; nread = 0;
@ -523,7 +523,7 @@ static ssize_t cf_msh3_recv(struct Curl_cfilter *cf, struct Curl_easy *data,
return -1; return -1;
} }
CF_DATA_SAVE(save, cf, data); CF_DATA_SAVE(save, cf, data);
DEBUGF(LOG_CF(data, cf, "req: recv with %zu byte buffer", len)); CURL_TRC_CF(data, cf, "req: recv with %zu byte buffer", len);
msh3_lock_acquire(&stream->recv_lock); msh3_lock_acquire(&stream->recv_lock);
@ -538,8 +538,8 @@ static ssize_t cf_msh3_recv(struct Curl_cfilter *cf, struct Curl_easy *data,
if(!Curl_bufq_is_empty(&stream->recvbuf)) { if(!Curl_bufq_is_empty(&stream->recvbuf)) {
nread = Curl_bufq_read(&stream->recvbuf, nread = Curl_bufq_read(&stream->recvbuf,
(unsigned char *)buf, len, err); (unsigned char *)buf, len, err);
DEBUGF(LOG_CF(data, cf, "read recvbuf(len=%zu) -> %zd, %d", CURL_TRC_CF(data, cf, "read recvbuf(len=%zu) -> %zd, %d",
len, nread, *err)); len, nread, *err);
if(nread < 0) if(nread < 0)
goto out; goto out;
if(stream->closed) if(stream->closed)
@ -550,7 +550,7 @@ static ssize_t cf_msh3_recv(struct Curl_cfilter *cf, struct Curl_easy *data,
goto out; goto out;
} }
else { else {
DEBUGF(LOG_CF(data, cf, "req: nothing here, call again")); CURL_TRC_CF(data, cf, "req: nothing here, call again");
*err = CURLE_AGAIN; *err = CURLE_AGAIN;
} }
@ -581,7 +581,7 @@ static ssize_t cf_msh3_send(struct Curl_cfilter *cf, struct Curl_easy *data,
/* Sizes must match for cast below to work" */ /* Sizes must match for cast below to work" */
DEBUGASSERT(stream); DEBUGASSERT(stream);
DEBUGF(LOG_CF(data, cf, "req: send %zu bytes", len)); CURL_TRC_CF(data, cf, "req: send %zu bytes", len);
if(!stream->req) { if(!stream->req) {
/* The first send on the request contains the headers and possibly some /* The first send on the request contains the headers and possibly some
@ -630,7 +630,7 @@ static ssize_t cf_msh3_send(struct Curl_cfilter *cf, struct Curl_easy *data,
break; break;
} }
DEBUGF(LOG_CF(data, cf, "req: send %zu headers", nheader)); CURL_TRC_CF(data, cf, "req: send %zu headers", nheader);
stream->req = MsH3RequestOpen(ctx->qconn, &msh3_request_if, data, stream->req = MsH3RequestOpen(ctx->qconn, &msh3_request_if, data,
nva, nheader, nva, nheader,
eos ? MSH3_REQUEST_FLAG_FIN : eos ? MSH3_REQUEST_FLAG_FIN :
@ -646,7 +646,7 @@ static ssize_t cf_msh3_send(struct Curl_cfilter *cf, struct Curl_easy *data,
} }
else { else {
/* request is open */ /* request is open */
DEBUGF(LOG_CF(data, cf, "req: send %zu body bytes", len)); CURL_TRC_CF(data, cf, "req: send %zu body bytes", len);
if(len > 0xFFFFFFFF) { if(len > 0xFFFFFFFF) {
len = 0xFFFFFFFF; len = 0xFFFFFFFF;
} }
@ -694,7 +694,7 @@ static int cf_msh3_get_select_socks(struct Curl_cfilter *cf,
drain_stream(cf, data); drain_stream(cf, data);
} }
} }
DEBUGF(LOG_CF(data, cf, "select_sock -> %d", bitmap)); CURL_TRC_CF(data, cf, "select_sock -> %d", bitmap);
CF_DATA_RESTORE(cf, save); CF_DATA_RESTORE(cf, save);
return bitmap; return bitmap;
} }
@ -711,8 +711,8 @@ static bool cf_msh3_data_pending(struct Curl_cfilter *cf,
(void)cf; (void)cf;
if(stream && stream->req) { if(stream && stream->req) {
msh3_lock_acquire(&stream->recv_lock); msh3_lock_acquire(&stream->recv_lock);
DEBUGF(LOG_CF((struct Curl_easy *)data, cf, "data pending = %zu", CURL_TRC_CF((struct Curl_easy *)data, cf, "data pending = %zu",
Curl_bufq_len(&stream->recvbuf))); Curl_bufq_len(&stream->recvbuf));
pending = !Curl_bufq_is_empty(&stream->recvbuf); pending = !Curl_bufq_is_empty(&stream->recvbuf);
msh3_lock_release(&stream->recv_lock); msh3_lock_release(&stream->recv_lock);
if(pending) if(pending)
@ -774,7 +774,7 @@ static CURLcode cf_msh3_data_event(struct Curl_cfilter *cf,
h3_data_done(cf, data); h3_data_done(cf, data);
break; break;
case CF_CTRL_DATA_DONE_SEND: case CF_CTRL_DATA_DONE_SEND:
DEBUGF(LOG_CF(data, cf, "req: send done")); CURL_TRC_CF(data, cf, "req: send done");
if(stream) { if(stream) {
stream->upload_done = TRUE; stream->upload_done = TRUE;
if(stream->req) { if(stream->req) {
@ -787,7 +787,7 @@ static CURLcode cf_msh3_data_event(struct Curl_cfilter *cf,
} }
break; break;
case CF_CTRL_CONN_INFO_UPDATE: case CF_CTRL_CONN_INFO_UPDATE:
DEBUGF(LOG_CF(data, cf, "req: update info")); CURL_TRC_CF(data, cf, "req: update info");
cf_msh3_active(cf, data); cf_msh3_active(cf, data);
break; break;
default: default:
@ -813,17 +813,17 @@ static CURLcode cf_connect_start(struct Curl_cfilter *cf,
/* TODO: need a way to provide trust anchors to MSH3 */ /* TODO: need a way to provide trust anchors to MSH3 */
#ifdef DEBUGBUILD #ifdef DEBUGBUILD
/* we need this for our test cases to run */ /* we need this for our test cases to run */
DEBUGF(LOG_CF(data, cf, "non-standard CA not supported, " CURL_TRC_CF(data, cf, "non-standard CA not supported, "
"switching off verifypeer in DEBUG mode")); "switching off verifypeer in DEBUG mode");
verify = 0; verify = 0;
#else #else
DEBUGF(LOG_CF(data, cf, "non-standard CA not supported, " CURL_TRC_CF(data, cf, "non-standard CA not supported, "
"attempting with built-in verification")); "attempting with built-in verification");
#endif #endif
} }
DEBUGF(LOG_CF(data, cf, "connecting to %s:%d (verify=%d)", CURL_TRC_CF(data, cf, "connecting to %s:%d (verify=%d)",
cf->conn->host.name, (int)cf->conn->remote_port, verify)); cf->conn->host.name, (int)cf->conn->remote_port, verify);
ctx->api = MsH3ApiOpen(); ctx->api = MsH3ApiOpen();
if(!ctx->api) { if(!ctx->api) {
@ -888,7 +888,7 @@ static CURLcode cf_msh3_connect(struct Curl_cfilter *cf,
if(ctx->handshake_complete) { if(ctx->handshake_complete) {
ctx->handshake_at = Curl_now(); ctx->handshake_at = Curl_now();
if(ctx->handshake_succeeded) { if(ctx->handshake_succeeded) {
DEBUGF(LOG_CF(data, cf, "handshake succeeded")); CURL_TRC_CF(data, cf, "handshake succeeded");
cf->conn->bits.multiplex = TRUE; /* at least potentially multiplexed */ cf->conn->bits.multiplex = TRUE; /* at least potentially multiplexed */
cf->conn->httpversion = 30; cf->conn->httpversion = 30;
cf->conn->bundle->multiuse = BUNDLE_MULTIPLEX; cf->conn->bundle->multiuse = BUNDLE_MULTIPLEX;
@ -918,7 +918,7 @@ static void cf_msh3_close(struct Curl_cfilter *cf, struct Curl_easy *data)
CF_DATA_SAVE(save, cf, data); CF_DATA_SAVE(save, cf, data);
if(ctx) { if(ctx) {
DEBUGF(LOG_CF(data, cf, "destroying")); CURL_TRC_CF(data, cf, "destroying");
if(ctx->qconn) { if(ctx->qconn) {
MsH3ConnectionClose(ctx->qconn); MsH3ConnectionClose(ctx->qconn);
ctx->qconn = NULL; ctx->qconn = NULL;
@ -935,13 +935,13 @@ static void cf_msh3_close(struct Curl_cfilter *cf, struct Curl_easy *data)
*/ */
ctx->active = FALSE; ctx->active = FALSE;
if(ctx->sock[SP_LOCAL] == cf->conn->sock[cf->sockindex]) { if(ctx->sock[SP_LOCAL] == cf->conn->sock[cf->sockindex]) {
DEBUGF(LOG_CF(data, cf, "cf_msh3_close(%d) active", CURL_TRC_CF(data, cf, "cf_msh3_close(%d) active",
(int)ctx->sock[SP_LOCAL])); (int)ctx->sock[SP_LOCAL]);
cf->conn->sock[cf->sockindex] = CURL_SOCKET_BAD; cf->conn->sock[cf->sockindex] = CURL_SOCKET_BAD;
} }
else { else {
DEBUGF(LOG_CF(data, cf, "cf_socket_close(%d) no longer at " CURL_TRC_CF(data, cf, "cf_socket_close(%d) no longer at "
"conn->sock[], discarding", (int)ctx->sock[SP_LOCAL])); "conn->sock[], discarding", (int)ctx->sock[SP_LOCAL]);
ctx->sock[SP_LOCAL] = CURL_SOCKET_BAD; ctx->sock[SP_LOCAL] = CURL_SOCKET_BAD;
} }
if(cf->sockindex == FIRSTSOCKET) if(cf->sockindex == FIRSTSOCKET)

140
lib/vquic/curl_ngtcp2.c
View File

@ -225,7 +225,7 @@ static CURLcode h3_data_setup(struct Curl_cfilter *cf,
stream->recv_buf_nonflow = 0; stream->recv_buf_nonflow = 0;
H3_STREAM_LCTX(data) = stream; H3_STREAM_LCTX(data) = stream;
DEBUGF(LOG_CF(data, cf, "data setup")); CURL_TRC_CF(data, cf, "data setup");
return CURLE_OK; return CURLE_OK;
} }
@ -235,8 +235,7 @@ static void h3_data_done(struct Curl_cfilter *cf, struct Curl_easy *data)
(void)cf; (void)cf;
if(stream) { if(stream) {
DEBUGF(LOG_CF(data, cf, "[h3sid=%"PRId64"] easy handle is done", CURL_TRC_CF(data, cf, "[h3sid=%"PRId64"] easy handle is done", stream->id);
stream->id));
Curl_bufq_free(&stream->sendbuf); Curl_bufq_free(&stream->sendbuf);
Curl_bufq_free(&stream->recvbuf); Curl_bufq_free(&stream->recvbuf);
free(stream); free(stream);
@ -544,15 +543,15 @@ static CURLcode quic_init_ssl(struct Curl_cfilter *cf,
gnutls_session_set_ptr(ctx->gtls->session, &ctx->conn_ref); gnutls_session_set_ptr(ctx->gtls->session, &ctx->conn_ref);
if(ngtcp2_crypto_gnutls_configure_client_session(ctx->gtls->session) != 0) { if(ngtcp2_crypto_gnutls_configure_client_session(ctx->gtls->session) != 0) {
DEBUGF(LOG_CF(data, cf, CURL_TRC_CF(data, cf,
"ngtcp2_crypto_gnutls_configure_client_session failed\n")); "ngtcp2_crypto_gnutls_configure_client_session failed\n");
return CURLE_QUIC_CONNECT_ERROR; return CURLE_QUIC_CONNECT_ERROR;
} }
rc = gnutls_priority_set_direct(ctx->gtls->session, QUIC_PRIORITY, NULL); rc = gnutls_priority_set_direct(ctx->gtls->session, QUIC_PRIORITY, NULL);
if(rc < 0) { if(rc < 0) {
DEBUGF(LOG_CF(data, cf, "gnutls_priority_set_direct failed: %s\n", CURL_TRC_CF(data, cf, "gnutls_priority_set_direct failed: %s\n",
gnutls_strerror(rc))); gnutls_strerror(rc));
return CURLE_QUIC_CONNECT_ERROR; return CURLE_QUIC_CONNECT_ERROR;
} }
@ -728,8 +727,8 @@ static void report_consumed_data(struct Curl_cfilter *cf,
} }
} }
if(consumed > 0) { if(consumed > 0) {
DEBUGF(LOG_CF(data, cf, "[h3sid=%" PRId64 "] consumed %zu DATA bytes", CURL_TRC_CF(data, cf, "[h3sid=%" PRId64 "] consumed %zu DATA bytes",
stream->id, consumed)); stream->id, consumed);
ngtcp2_conn_extend_max_stream_offset(ctx->qconn, stream->id, ngtcp2_conn_extend_max_stream_offset(ctx->qconn, stream->id,
consumed); consumed);
ngtcp2_conn_extend_max_offset(ctx->qconn, consumed); ngtcp2_conn_extend_max_offset(ctx->qconn, consumed);
@ -751,8 +750,8 @@ static int cb_recv_stream_data(ngtcp2_conn *tconn, uint32_t flags,
nconsumed = nconsumed =
nghttp3_conn_read_stream(ctx->h3conn, stream_id, buf, buflen, fin); nghttp3_conn_read_stream(ctx->h3conn, stream_id, buf, buflen, fin);
DEBUGF(LOG_CF(data, cf, "[h3sid=%" PRId64 "] read_stream(len=%zu) -> %zd", CURL_TRC_CF(data, cf, "[h3sid=%" PRId64 "] read_stream(len=%zu) -> %zd",
stream_id, buflen, nconsumed)); stream_id, buflen, nconsumed);
if(nconsumed < 0) { if(nconsumed < 0) {
ngtcp2_ccerr_set_application_error( ngtcp2_ccerr_set_application_error(
&ctx->last_error, &ctx->last_error,
@ -810,8 +809,8 @@ static int cb_stream_close(ngtcp2_conn *tconn, uint32_t flags,
rv = nghttp3_conn_close_stream(ctx->h3conn, stream3_id, rv = nghttp3_conn_close_stream(ctx->h3conn, stream3_id,
app_error_code); app_error_code);
DEBUGF(LOG_CF(data, cf, "[h3sid=%" PRId64 "] quic close(err=%" CURL_TRC_CF(data, cf, "[h3sid=%" PRId64 "] quic close(err=%"
PRIu64 ") -> %d", stream3_id, app_error_code, rv)); PRIu64 ") -> %d", stream3_id, app_error_code, rv);
if(rv) { if(rv) {
ngtcp2_ccerr_set_application_error( ngtcp2_ccerr_set_application_error(
&ctx->last_error, nghttp3_err_infer_quic_app_error_code(rv), NULL, 0); &ctx->last_error, nghttp3_err_infer_quic_app_error_code(rv), NULL, 0);
@ -835,7 +834,7 @@ static int cb_stream_reset(ngtcp2_conn *tconn, int64_t stream_id,
(void)data; (void)data;
rv = nghttp3_conn_shutdown_stream_read(ctx->h3conn, stream_id); rv = nghttp3_conn_shutdown_stream_read(ctx->h3conn, stream_id);
DEBUGF(LOG_CF(data, cf, "[h3sid=%" PRId64 "] reset -> %d", stream_id, rv)); CURL_TRC_CF(data, cf, "[h3sid=%" PRId64 "] reset -> %d", stream_id, rv);
if(rv) { if(rv) {
return NGTCP2_ERR_CALLBACK_FAILURE; return NGTCP2_ERR_CALLBACK_FAILURE;
} }
@ -1064,8 +1063,6 @@ static int cf_ngtcp2_get_select_socks(struct Curl_cfilter *cf,
stream && nghttp3_conn_is_stream_writable(ctx->h3conn, stream->id)) stream && nghttp3_conn_is_stream_writable(ctx->h3conn, stream->id))
rv |= GETSOCK_WRITESOCK(0); rv |= GETSOCK_WRITESOCK(0);
/* DEBUGF(LOG_CF(data, cf, "get_select_socks -> %x (sock=%d)",
rv, (int)socks[0])); */
CF_DATA_RESTORE(cf, save); CF_DATA_RESTORE(cf, save);
return rv; return rv;
} }
@ -1102,8 +1099,8 @@ static int cb_h3_stream_close(nghttp3_conn *conn, int64_t stream_id,
if(!stream) if(!stream)
return 0; return 0;
DEBUGF(LOG_CF(data, cf, "[h3sid=%" PRId64 "] h3 close(err=%" PRId64 ")", CURL_TRC_CF(data, cf, "[h3sid=%" PRId64 "] h3 close(err=%" PRId64 ")",
stream_id, app_error_code)); stream_id, app_error_code);
stream->closed = TRUE; stream->closed = TRUE;
stream->error3 = app_error_code; stream->error3 = app_error_code;
if(app_error_code == NGHTTP3_H3_INTERNAL_ERROR) { if(app_error_code == NGHTTP3_H3_INTERNAL_ERROR) {
@ -1133,9 +1130,6 @@ static CURLcode write_resp_raw(struct Curl_cfilter *cf,
return CURLE_RECV_ERROR; return CURLE_RECV_ERROR;
} }
nwritten = Curl_bufq_write(&stream->recvbuf, mem, memlen, &result); nwritten = Curl_bufq_write(&stream->recvbuf, mem, memlen, &result);
/* DEBUGF(LOG_CF(data, cf, "[h3sid=%" PRId64 "] add recvbuf(len=%zu) "
"-> %zd, %d", stream->id, memlen, nwritten, result));
*/
if(nwritten < 0) { if(nwritten < 0) {
return result; return result;
} }
@ -1204,8 +1198,8 @@ static int cb_h3_end_headers(nghttp3_conn *conn, int64_t stream_id,
return -1; return -1;
} }
DEBUGF(LOG_CF(data, cf, "[h3sid=%" PRId64 "] end_headers(status_code=%d", CURL_TRC_CF(data, cf, "[h3sid=%" PRId64 "] end_headers(status_code=%d",
stream_id, stream->status_code)); stream_id, stream->status_code);
if(stream->status_code / 100 != 1) { if(stream->status_code / 100 != 1) {
stream->resp_hds_complete = TRUE; stream->resp_hds_complete = TRUE;
} }
@ -1244,8 +1238,7 @@ static int cb_h3_recv_header(nghttp3_conn *conn, int64_t stream_id,
return -1; return -1;
ncopy = msnprintf(line, sizeof(line), "HTTP/3 %03d \r\n", ncopy = msnprintf(line, sizeof(line), "HTTP/3 %03d \r\n",
stream->status_code); stream->status_code);
DEBUGF(LOG_CF(data, cf, "[h3sid=%" PRId64 "] status: %s", CURL_TRC_CF(data, cf, "[h3sid=%" PRId64 "] status: %s", stream_id, line);
stream_id, line));
result = write_resp_raw(cf, data, line, ncopy, FALSE); result = write_resp_raw(cf, data, line, ncopy, FALSE);
if(result) { if(result) {
return -1; return -1;
@ -1253,9 +1246,9 @@ static int cb_h3_recv_header(nghttp3_conn *conn, int64_t stream_id,
} }
else { else {
/* store as an HTTP1-style header */ /* store as an HTTP1-style header */
DEBUGF(LOG_CF(data, cf, "[h3sid=%" PRId64 "] header: %.*s: %.*s", CURL_TRC_CF(data, cf, "[h3sid=%" PRId64 "] header: %.*s: %.*s",
stream_id, (int)h3name.len, h3name.base, stream_id, (int)h3name.len, h3name.base,
(int)h3val.len, h3val.base)); (int)h3val.len, h3val.base);
result = write_resp_raw(cf, data, h3name.base, h3name.len, FALSE); result = write_resp_raw(cf, data, h3name.base, h3name.len, FALSE);
if(result) { if(result) {
return -1; return -1;
@ -1307,7 +1300,7 @@ static int cb_h3_reset_stream(nghttp3_conn *conn, int64_t stream_id,
rv = ngtcp2_conn_shutdown_stream_write(ctx->qconn, 0, stream_id, rv = ngtcp2_conn_shutdown_stream_write(ctx->qconn, 0, stream_id,
app_error_code); app_error_code);
DEBUGF(LOG_CF(data, cf, "[h3sid=%" PRId64 "] reset -> %d", stream_id, rv)); CURL_TRC_CF(data, cf, "[h3sid=%" PRId64 "] reset -> %d", stream_id, rv);
if(rv && rv != NGTCP2_ERR_STREAM_NOT_FOUND) { if(rv && rv != NGTCP2_ERR_STREAM_NOT_FOUND) {
return NGTCP2_ERR_CALLBACK_FAILURE; return NGTCP2_ERR_CALLBACK_FAILURE;
} }
@ -1405,8 +1398,8 @@ static ssize_t recv_closed_stream(struct Curl_cfilter *cf,
failf(data, failf(data,
"HTTP/3 stream %" PRId64 " reset by server", stream->id); "HTTP/3 stream %" PRId64 " reset by server", stream->id);
*err = CURLE_PARTIAL_FILE; *err = CURLE_PARTIAL_FILE;
DEBUGF(LOG_CF(data, cf, "[h3sid=%" PRId64 "] cf_recv, was reset -> %d", CURL_TRC_CF(data, cf, "[h3sid=%" PRId64 "] cf_recv, was reset -> %d",
stream->id, *err)); stream->id, *err);
goto out; goto out;
} }
else if(stream->error3 != NGHTTP3_H3_NO_ERROR) { else if(stream->error3 != NGHTTP3_H3_NO_ERROR) {
@ -1414,8 +1407,8 @@ static ssize_t recv_closed_stream(struct Curl_cfilter *cf,
"HTTP/3 stream %" PRId64 " was not closed cleanly: " "HTTP/3 stream %" PRId64 " was not closed cleanly: "
"(err %"PRId64")", stream->id, stream->error3); "(err %"PRId64")", stream->id, stream->error3);
*err = CURLE_HTTP3; *err = CURLE_HTTP3;
DEBUGF(LOG_CF(data, cf, "[h3sid=%" PRId64 "] cf_recv, closed uncleanly" CURL_TRC_CF(data, cf, "[h3sid=%" PRId64 "] cf_recv, closed uncleanly"
" -> %d", stream->id, *err)); " -> %d", stream->id, *err);
goto out; goto out;
} }
@ -1425,13 +1418,13 @@ static ssize_t recv_closed_stream(struct Curl_cfilter *cf,
" all response header fields, treated as error", " all response header fields, treated as error",
stream->id); stream->id);
*err = CURLE_HTTP3; *err = CURLE_HTTP3;
DEBUGF(LOG_CF(data, cf, "[h3sid=%" PRId64 "] cf_recv, closed incomplete" CURL_TRC_CF(data, cf, "[h3sid=%" PRId64 "] cf_recv, closed incomplete"
" -> %d", stream->id, *err)); " -> %d", stream->id, *err);
goto out; goto out;
} }
else { else {
DEBUGF(LOG_CF(data, cf, "[h3sid=%" PRId64 "] cf_recv, closed ok" CURL_TRC_CF(data, cf, "[h3sid=%" PRId64 "] cf_recv, closed ok"
" -> %d", stream->id, *err)); " -> %d", stream->id, *err);
} }
*err = CURLE_OK; *err = CURLE_OK;
nread = 0; nread = 0;
@ -1469,8 +1462,8 @@ static ssize_t cf_ngtcp2_recv(struct Curl_cfilter *cf, struct Curl_easy *data,
if(!Curl_bufq_is_empty(&stream->recvbuf)) { if(!Curl_bufq_is_empty(&stream->recvbuf)) {
nread = Curl_bufq_read(&stream->recvbuf, nread = Curl_bufq_read(&stream->recvbuf,
(unsigned char *)buf, len, err); (unsigned char *)buf, len, err);
DEBUGF(LOG_CF(data, cf, "[h3sid=%" PRId64 "] read recvbuf(len=%zu) " CURL_TRC_CF(data, cf, "[h3sid=%" PRId64 "] read recvbuf(len=%zu) "
"-> %zd, %d", stream->id, len, nread, *err)); "-> %zd, %d", stream->id, len, nread, *err);
if(nread < 0) if(nread < 0)
goto out; goto out;
report_consumed_data(cf, data, nread); report_consumed_data(cf, data, nread);
@ -1486,8 +1479,8 @@ static ssize_t cf_ngtcp2_recv(struct Curl_cfilter *cf, struct Curl_easy *data,
if(nread < 0 && !Curl_bufq_is_empty(&stream->recvbuf)) { if(nread < 0 && !Curl_bufq_is_empty(&stream->recvbuf)) {
nread = Curl_bufq_read(&stream->recvbuf, nread = Curl_bufq_read(&stream->recvbuf,
(unsigned char *)buf, len, err); (unsigned char *)buf, len, err);
DEBUGF(LOG_CF(data, cf, "[h3sid=%" PRId64 "] read recvbuf(len=%zu) " CURL_TRC_CF(data, cf, "[h3sid=%" PRId64 "] read recvbuf(len=%zu) "
"-> %zd, %d", stream->id, len, nread, *err)); "-> %zd, %d", stream->id, len, nread, *err);
if(nread < 0) if(nread < 0)
goto out; goto out;
report_consumed_data(cf, data, nread); report_consumed_data(cf, data, nread);
@ -1517,8 +1510,8 @@ out:
nread = -1; nread = -1;
} }
} }
DEBUGF(LOG_CF(data, cf, "[h3sid=%" PRId64 "] cf_recv(len=%zu) -> %zd, %d", CURL_TRC_CF(data, cf, "[h3sid=%" PRId64 "] cf_recv(len=%zu) -> %zd, %d",
stream? stream->id : -1, len, nread, *err)); stream? stream->id : -1, len, nread, *err);
CF_DATA_RESTORE(cf, save); CF_DATA_RESTORE(cf, save);
return nread; return nread;
} }
@ -1555,8 +1548,7 @@ static int cb_h3_acked_req_body(nghttp3_conn *conn, int64_t stream_id,
(data->req.keepon & KEEP_SEND)) { (data->req.keepon & KEEP_SEND)) {
data->req.keepon &= ~KEEP_SEND_HOLD; data->req.keepon &= ~KEEP_SEND_HOLD;
h3_drain_stream(cf, data); h3_drain_stream(cf, data);
DEBUGF(LOG_CF(data, cf, "[h3sid=%" PRId64 "] unpausing acks", CURL_TRC_CF(data, cf, "[h3sid=%" PRId64 "] unpausing acks", stream_id);
stream_id));
} }
} }
return 0; return 0;
@ -1613,18 +1605,18 @@ cb_h3_read_req_body(nghttp3_conn *conn, int64_t stream_id,
} }
else if(!nwritten) { else if(!nwritten) {
/* Not EOF, and nothing to give, we signal WOULDBLOCK. */ /* Not EOF, and nothing to give, we signal WOULDBLOCK. */
DEBUGF(LOG_CF(data, cf, "[h3sid=%" PRId64 "] read req body -> AGAIN", CURL_TRC_CF(data, cf, "[h3sid=%" PRId64 "] read req body -> AGAIN",
stream->id)); stream->id);
return NGHTTP3_ERR_WOULDBLOCK; return NGHTTP3_ERR_WOULDBLOCK;
} }
DEBUGF(LOG_CF(data, cf, "[h3sid=%" PRId64 "] read req body -> " CURL_TRC_CF(data, cf, "[h3sid=%" PRId64 "] read req body -> "
"%d vecs%s with %zu (buffered=%zu, left=%" "%d vecs%s with %zu (buffered=%zu, left=%"
CURL_FORMAT_CURL_OFF_T ")", CURL_FORMAT_CURL_OFF_T ")",
stream->id, (int)nvecs, stream->id, (int)nvecs,
*pflags == NGHTTP3_DATA_FLAG_EOF?" EOF":"", *pflags == NGHTTP3_DATA_FLAG_EOF?" EOF":"",
nwritten, Curl_bufq_len(&stream->sendbuf), nwritten, Curl_bufq_len(&stream->sendbuf),
stream->upload_left)); stream->upload_left);
return (nghttp3_ssize)nvecs; return (nghttp3_ssize)nvecs;
} }
@ -1723,12 +1715,12 @@ static ssize_t h3_stream_open(struct Curl_cfilter *cf,
if(rc) { if(rc) {
switch(rc) { switch(rc) {
case NGHTTP3_ERR_CONN_CLOSING: case NGHTTP3_ERR_CONN_CLOSING:
DEBUGF(LOG_CF(data, cf, "h3sid[%"PRId64"] failed to send, " CURL_TRC_CF(data, cf, "h3sid[%"PRId64"] failed to send, "
"connection is closing", stream->id)); "connection is closing", stream->id);
break; break;
default: default:
DEBUGF(LOG_CF(data, cf, "h3sid[%"PRId64"] failed to send -> %d (%s)", CURL_TRC_CF(data, cf, "h3sid[%"PRId64"] failed to send -> %d (%s)",
stream->id, rc, ngtcp2_strerror(rc))); stream->id, rc, ngtcp2_strerror(rc));
break; break;
} }
*err = CURLE_SEND_ERROR; *err = CURLE_SEND_ERROR;
@ -1737,8 +1729,8 @@ static ssize_t h3_stream_open(struct Curl_cfilter *cf,
} }
infof(data, "Using HTTP/3 Stream ID: %" PRId64, stream->id); infof(data, "Using HTTP/3 Stream ID: %" PRId64, stream->id);
DEBUGF(LOG_CF(data, cf, "[h3sid=%" PRId64 "] opened for %s", CURL_TRC_CF(data, cf, "[h3sid=%" PRId64 "] opened for %s",
stream->id, data->state.url)); stream->id, data->state.url);
out: out:
free(nva); free(nva);
@ -1773,7 +1765,7 @@ static ssize_t cf_ngtcp2_send(struct Curl_cfilter *cf, struct Curl_easy *data,
if(!stream || stream->id < 0) { if(!stream || stream->id < 0) {
sent = h3_stream_open(cf, data, buf, len, err); sent = h3_stream_open(cf, data, buf, len, err);
if(sent < 0) { if(sent < 0) {
DEBUGF(LOG_CF(data, cf, "failed to open stream -> %d", *err)); CURL_TRC_CF(data, cf, "failed to open stream -> %d", *err);
goto out; goto out;
} }
} }
@ -1799,9 +1791,9 @@ static ssize_t cf_ngtcp2_send(struct Curl_cfilter *cf, struct Curl_easy *data,
} }
else { else {
sent = Curl_bufq_write(&stream->sendbuf, buf, len, err); sent = Curl_bufq_write(&stream->sendbuf, buf, len, err);
DEBUGF(LOG_CF(data, cf, "[h3sid=%" PRId64 "] cf_send, add to " CURL_TRC_CF(data, cf, "[h3sid=%" PRId64 "] cf_send, add to "
"sendbuf(len=%zu) -> %zd, %d", "sendbuf(len=%zu) -> %zd, %d",
stream->id, len, sent, *err)); stream->id, len, sent, *err);
if(sent < 0) { if(sent < 0) {
goto out; goto out;
} }
@ -1821,9 +1813,9 @@ static ssize_t cf_ngtcp2_send(struct Curl_cfilter *cf, struct Curl_easy *data,
* "written" into our various internal connection buffers. * "written" into our various internal connection buffers.
* We put the stream upload on HOLD, until this gets ACKed. */ * We put the stream upload on HOLD, until this gets ACKed. */
stream->upload_blocked_len = sent; stream->upload_blocked_len = sent;
DEBUGF(LOG_CF(data, cf, "[h3sid=%" PRId64 "] cf_send(len=%zu), " CURL_TRC_CF(data, cf, "[h3sid=%" PRId64 "] cf_send(len=%zu), "
"%zu bytes in flight -> EGAIN", stream->id, len, "%zu bytes in flight -> EGAIN", stream->id, len,
stream->sendbuf_len_in_flight)); stream->sendbuf_len_in_flight);
*err = CURLE_AGAIN; *err = CURLE_AGAIN;
sent = -1; sent = -1;
data->req.keepon |= KEEP_SEND_HOLD; data->req.keepon |= KEEP_SEND_HOLD;
@ -1835,8 +1827,8 @@ out:
*err = result; *err = result;
sent = -1; sent = -1;
} }
DEBUGF(LOG_CF(data, cf, "[h3sid=%" PRId64 "] cf_send(len=%zu) -> %zd, %d", CURL_TRC_CF(data, cf, "[h3sid=%" PRId64 "] cf_send(len=%zu) -> %zd, %d",
stream? stream->id : -1, len, sent, *err)); stream? stream->id : -1, len, sent, *err);
CF_DATA_RESTORE(cf, save); CF_DATA_RESTORE(cf, save);
return sent; return sent;
} }
@ -1913,8 +1905,8 @@ static CURLcode recv_pkt(const unsigned char *pkt, size_t pktlen,
rv = ngtcp2_conn_read_pkt(ctx->qconn, &path, &pi, pkt, pktlen, pktx->ts); rv = ngtcp2_conn_read_pkt(ctx->qconn, &path, &pi, pkt, pktlen, pktx->ts);
if(rv) { if(rv) {
DEBUGF(LOG_CF(pktx->data, pktx->cf, "ingress, read_pkt -> %s", CURL_TRC_CF(pktx->data, pktx->cf, "ingress, read_pkt -> %s",
ngtcp2_strerror(rv))); ngtcp2_strerror(rv));
if(!ctx->last_error.error_code) { if(!ctx->last_error.error_code) {
if(rv == NGTCP2_ERR_CRYPTO) { if(rv == NGTCP2_ERR_CRYPTO) {
ngtcp2_ccerr_set_tls_alert(&ctx->last_error, ngtcp2_ccerr_set_tls_alert(&ctx->last_error,
@ -2129,8 +2121,6 @@ static CURLcode cf_progress_egress(struct Curl_cfilter *cf,
/* add the next packet to send, if any, to our buffer */ /* add the next packet to send, if any, to our buffer */
nread = Curl_bufq_sipn(&ctx->q.sendbuf, max_payload_size, nread = Curl_bufq_sipn(&ctx->q.sendbuf, max_payload_size,
read_pkt_to_send, pktx, &curlcode); read_pkt_to_send, pktx, &curlcode);
/* DEBUGF(LOG_CF(data, cf, "sip packet(maxlen=%zu) -> %zd, %d",
max_payload_size, nread, curlcode)); */
if(nread < 0) { if(nread < 0) {
if(curlcode != CURLE_AGAIN) if(curlcode != CURLE_AGAIN)
return curlcode; return curlcode;
@ -2305,7 +2295,7 @@ static void cf_ngtcp2_close(struct Curl_cfilter *cf, struct Curl_easy *data)
ngtcp2_tstamp ts; ngtcp2_tstamp ts;
ngtcp2_ssize rc; ngtcp2_ssize rc;
DEBUGF(LOG_CF(data, cf, "close")); CURL_TRC_CF(data, cf, "close");
ts = timestamp(); ts = timestamp();
rc = ngtcp2_conn_write_connection_close(ctx->qconn, NULL, /* path */ rc = ngtcp2_conn_write_connection_close(ctx->qconn, NULL, /* path */
NULL, /* pkt_info */ NULL, /* pkt_info */
@ -2329,7 +2319,7 @@ static void cf_ngtcp2_destroy(struct Curl_cfilter *cf, struct Curl_easy *data)
struct cf_call_data save; struct cf_call_data save;
CF_DATA_SAVE(save, cf, data); CF_DATA_SAVE(save, cf, data);
DEBUGF(LOG_CF(data, cf, "destroy")); CURL_TRC_CF(data, cf, "destroy");
if(ctx) { if(ctx) {
cf_ngtcp2_ctx_clear(ctx); cf_ngtcp2_ctx_clear(ctx);
free(ctx); free(ctx);
@ -2460,7 +2450,7 @@ static CURLcode cf_ngtcp2_connect(struct Curl_cfilter *cf,
if(ctx->reconnect_at.tv_sec && Curl_timediff(now, ctx->reconnect_at) < 0) { if(ctx->reconnect_at.tv_sec && Curl_timediff(now, ctx->reconnect_at) < 0) {
/* Not time yet to attempt the next connect */ /* Not time yet to attempt the next connect */
DEBUGF(LOG_CF(data, cf, "waiting for reconnect time")); CURL_TRC_CF(data, cf, "waiting for reconnect time");
goto out; goto out;
} }
@ -2484,11 +2474,11 @@ static CURLcode cf_ngtcp2_connect(struct Curl_cfilter *cf,
if(ngtcp2_conn_get_handshake_completed(ctx->qconn)) { if(ngtcp2_conn_get_handshake_completed(ctx->qconn)) {
ctx->handshake_at = now; ctx->handshake_at = now;
DEBUGF(LOG_CF(data, cf, "handshake complete after %dms", CURL_TRC_CF(data, cf, "handshake complete after %dms",
(int)Curl_timediff(now, ctx->started_at))); (int)Curl_timediff(now, ctx->started_at));
result = qng_verify_peer(cf, data); result = qng_verify_peer(cf, data);
if(!result) { if(!result) {
DEBUGF(LOG_CF(data, cf, "peer verified")); CURL_TRC_CF(data, cf, "peer verified");
cf->connected = TRUE; cf->connected = TRUE;
cf->conn->alpn = CURL_HTTP_VERSION_3; cf->conn->alpn = CURL_HTTP_VERSION_3;
*done = TRUE; *done = TRUE;
@ -2510,8 +2500,8 @@ out:
*/ */
int reconn_delay_ms = 200; int reconn_delay_ms = 200;
DEBUGF(LOG_CF(data, cf, "connect, remote closed, reconnect after %dms", CURL_TRC_CF(data, cf, "connect, remote closed, reconnect after %dms",
reconn_delay_ms)); reconn_delay_ms);
Curl_conn_cf_close(cf->next, data); Curl_conn_cf_close(cf->next, data);
cf_ngtcp2_ctx_clear(ctx); cf_ngtcp2_ctx_clear(ctx);
result = Curl_conn_cf_connect(cf->next, data, FALSE, done); result = Curl_conn_cf_connect(cf->next, data, FALSE, done);
@ -2538,7 +2528,7 @@ out:
if(!result && ctx->qconn) { if(!result && ctx->qconn) {
result = check_and_set_expiry(cf, data, &pktx); result = check_and_set_expiry(cf, data, &pktx);
} }
DEBUGF(LOG_CF(data, cf, "connect -> %d, done=%d", result, *done)); CURL_TRC_CF(data, cf, "connect -> %d, done=%d", result, *done);
CF_DATA_RESTORE(cf, save); CF_DATA_RESTORE(cf, save);
return result; return result;
} }
@ -2562,7 +2552,7 @@ static CURLcode cf_ngtcp2_query(struct Curl_cfilter *cf,
INT_MAX : (int)rp->initial_max_streams_bidi; INT_MAX : (int)rp->initial_max_streams_bidi;
else /* not arrived yet? */ else /* not arrived yet? */
*pres1 = Curl_multi_max_concurrent_streams(data->multi); *pres1 = Curl_multi_max_concurrent_streams(data->multi);
DEBUGF(LOG_CF(data, cf, "query max_conncurrent -> %d", *pres1)); CURL_TRC_CF(data, cf, "query max_conncurrent -> %d", *pres1);
CF_DATA_RESTORE(cf, save); CF_DATA_RESTORE(cf, save);
return CURLE_OK; return CURLE_OK;
} }

147
lib/vquic/curl_quiche.c
View File

@ -217,11 +217,10 @@ static void stream_send_suspend(struct Curl_cfilter *cf,
data->req.keepon |= KEEP_SEND_HOLD; data->req.keepon |= KEEP_SEND_HOLD;
++ctx->sends_on_hold; ++ctx->sends_on_hold;
if(H3_STREAM_ID(data) >= 0) if(H3_STREAM_ID(data) >= 0)
DEBUGF(LOG_CF(data, cf, "[h3sid=%"PRId64"] suspend sending", CURL_TRC_CF(data, cf, "[h3sid=%"PRId64"] suspend sending",
H3_STREAM_ID(data))); H3_STREAM_ID(data));
else else
DEBUGF(LOG_CF(data, cf, "[%s] suspend sending", CURL_TRC_CF(data, cf, "[%s] suspend sending", data->state.url);
data->state.url));
} }
} }
@ -234,11 +233,10 @@ static void stream_send_resume(struct Curl_cfilter *cf,
data->req.keepon &= ~KEEP_SEND_HOLD; data->req.keepon &= ~KEEP_SEND_HOLD;
--ctx->sends_on_hold; --ctx->sends_on_hold;
if(H3_STREAM_ID(data) >= 0) if(H3_STREAM_ID(data) >= 0)
DEBUGF(LOG_CF(data, cf, "[h3sid=%"PRId64"] resume sending", CURL_TRC_CF(data, cf, "[h3sid=%"PRId64"] resume sending",
H3_STREAM_ID(data))); H3_STREAM_ID(data));
else else
DEBUGF(LOG_CF(data, cf, "[%s] resume sending", CURL_TRC_CF(data, cf, "[%s] resume sending", data->state.url);
data->state.url));
Curl_expire(data, 0, EXPIRE_RUN_NOW); Curl_expire(data, 0, EXPIRE_RUN_NOW);
} }
} }
@ -277,7 +275,7 @@ static CURLcode h3_data_setup(struct Curl_cfilter *cf,
stream->id = -1; stream->id = -1;
Curl_bufq_initp(&stream->recvbuf, &ctx->stream_bufcp, Curl_bufq_initp(&stream->recvbuf, &ctx->stream_bufcp,
H3_STREAM_RECV_CHUNKS, BUFQ_OPT_SOFT_LIMIT); H3_STREAM_RECV_CHUNKS, BUFQ_OPT_SOFT_LIMIT);
DEBUGF(LOG_CF(data, cf, "data setup")); CURL_TRC_CF(data, cf, "data setup");
return CURLE_OK; return CURLE_OK;
} }
@ -288,8 +286,7 @@ static void h3_data_done(struct Curl_cfilter *cf, struct Curl_easy *data)
(void)cf; (void)cf;
if(stream) { if(stream) {
DEBUGF(LOG_CF(data, cf, "[h3sid=%"PRId64"] easy handle is done", CURL_TRC_CF(data, cf, "[h3sid=%"PRId64"] easy handle is done", stream->id);
stream->id));
if(stream_send_is_suspended(data)) { if(stream_send_is_suspended(data)) {
data->req.keepon &= ~KEEP_SEND_HOLD; data->req.keepon &= ~KEEP_SEND_HOLD;
--ctx->sends_on_hold; --ctx->sends_on_hold;
@ -397,10 +394,10 @@ static int cb_each_header(uint8_t *name, size_t name_len,
result = write_resp_raw(x->cf, x->data, "\r\n", 2); result = write_resp_raw(x->cf, x->data, "\r\n", 2);
} }
if(result) { if(result) {
DEBUGF(LOG_CF(x->data, x->cf, CURL_TRC_CF(x->data, x->cf,
"[h3sid=%"PRId64"][HEADERS][%.*s: %.*s] error %d", "[h3sid=%"PRId64"][HEADERS][%.*s: %.*s] error %d",
stream? stream->id : -1, (int)name_len, name, stream? stream->id : -1, (int)name_len, name,
(int)value_len, value, result)); (int)value_len, value, result);
} }
return result; return result;
} }
@ -455,8 +452,8 @@ static CURLcode cf_recv_body(struct Curl_cfilter *cf,
stream_resp_read, &cb_ctx, &result); stream_resp_read, &cb_ctx, &result);
if(nwritten < 0 && result != CURLE_AGAIN) { if(nwritten < 0 && result != CURLE_AGAIN) {
DEBUGF(LOG_CF(data, cf, "[h3sid=%"PRId64"] recv_body error %zd", CURL_TRC_CF(data, cf, "[h3sid=%"PRId64"] recv_body error %zd",
stream->id, nwritten)); stream->id, nwritten);
failf(data, "Error %d in HTTP/3 response body for stream[%"PRId64"]", failf(data, "Error %d in HTTP/3 response body for stream[%"PRId64"]",
result, stream->id); result, stream->id);
stream->closed = TRUE; stream->closed = TRUE;
@ -514,7 +511,7 @@ static CURLcode h3_process_event(struct Curl_cfilter *cf,
rc, stream3_id); rc, stream3_id);
return CURLE_RECV_ERROR; return CURLE_RECV_ERROR;
} }
DEBUGF(LOG_CF(data, cf, "[h3sid=%"PRId64"][HEADERS]", stream3_id)); CURL_TRC_CF(data, cf, "[h3sid=%"PRId64"][HEADERS]", stream3_id);
break; break;
case QUICHE_H3_EVENT_DATA: case QUICHE_H3_EVENT_DATA:
@ -524,7 +521,7 @@ static CURLcode h3_process_event(struct Curl_cfilter *cf,
break; break;
case QUICHE_H3_EVENT_RESET: case QUICHE_H3_EVENT_RESET:
DEBUGF(LOG_CF(data, cf, "[h3sid=%"PRId64"][RESET]", stream3_id)); CURL_TRC_CF(data, cf, "[h3sid=%"PRId64"][RESET]", stream3_id);
stream->closed = TRUE; stream->closed = TRUE;
stream->reset = TRUE; stream->reset = TRUE;
stream->send_closed = TRUE; stream->send_closed = TRUE;
@ -532,7 +529,7 @@ static CURLcode h3_process_event(struct Curl_cfilter *cf,
break; break;
case QUICHE_H3_EVENT_FINISHED: case QUICHE_H3_EVENT_FINISHED:
DEBUGF(LOG_CF(data, cf, "[h3sid=%"PRId64"][FINISHED]", stream3_id)); CURL_TRC_CF(data, cf, "[h3sid=%"PRId64"][FINISHED]", stream3_id);
if(!stream->resp_hds_complete) { if(!stream->resp_hds_complete) {
result = write_resp_raw(cf, data, "\r\n", 2); result = write_resp_raw(cf, data, "\r\n", 2);
if(result) if(result)
@ -544,12 +541,12 @@ static CURLcode h3_process_event(struct Curl_cfilter *cf,
break; break;
case QUICHE_H3_EVENT_GOAWAY: case QUICHE_H3_EVENT_GOAWAY:
DEBUGF(LOG_CF(data, cf, "[h3sid=%"PRId64"][GOAWAY]", stream3_id)); CURL_TRC_CF(data, cf, "[h3sid=%"PRId64"][GOAWAY]", stream3_id);
break; break;
default: default:
DEBUGF(LOG_CF(data, cf, "[h3sid=%"PRId64"] recv, unhandled event %d", CURL_TRC_CF(data, cf, "[h3sid=%"PRId64"] recv, unhandled event %d",
stream3_id, quiche_h3_event_type(ev))); stream3_id, quiche_h3_event_type(ev));
break; break;
} }
return result; return result;
@ -571,26 +568,25 @@ static CURLcode cf_poll_events(struct Curl_cfilter *cf,
break; break;
} }
else if(stream3_id < 0) { else if(stream3_id < 0) {
DEBUGF(LOG_CF(data, cf, "[h3sid=%"PRId64"] error poll: %"PRId64, CURL_TRC_CF(data, cf, "[h3sid=%"PRId64"] error poll: %"PRId64,
stream? stream->id : -1, stream3_id)); stream? stream->id : -1, stream3_id);
return CURLE_HTTP3; return CURLE_HTTP3;
} }
sdata = get_stream_easy(cf, data, stream3_id); sdata = get_stream_easy(cf, data, stream3_id);
if(!sdata) { if(!sdata) {
DEBUGF(LOG_CF(data, cf, "[h3sid=%"PRId64"] discard event %s for " CURL_TRC_CF(data, cf, "[h3sid=%"PRId64"] discard event %s for "
"unknown [h3sid=%"PRId64"]", "unknown [h3sid=%"PRId64"]",
stream? stream->id : -1, cf_ev_name(ev), stream? stream->id : -1, cf_ev_name(ev), stream3_id);
stream3_id));
} }
else { else {
result = h3_process_event(cf, sdata, stream3_id, ev); result = h3_process_event(cf, sdata, stream3_id, ev);
drain_stream(cf, sdata); drain_stream(cf, sdata);
if(result) { if(result) {
DEBUGF(LOG_CF(data, cf, "[h3sid=%"PRId64"] error processing event %s " CURL_TRC_CF(data, cf, "[h3sid=%"PRId64"] error processing event %s "
"for [h3sid=%"PRId64"] -> %d", "for [h3sid=%"PRId64"] -> %d",
stream? stream->id : -1, cf_ev_name(ev), stream? stream->id : -1, cf_ev_name(ev),
stream3_id, result)); stream3_id, result);
if(data == sdata) { if(data == sdata) {
/* Only report this error to the caller if it is about the /* Only report this error to the caller if it is about the
* transfer we were called with. Otherwise we fail a transfer * transfer we were called with. Otherwise we fail a transfer
@ -633,7 +629,7 @@ static CURLcode recv_pkt(const unsigned char *pkt, size_t pktlen,
&recv_info); &recv_info);
if(nread < 0) { if(nread < 0) {
if(QUICHE_ERR_DONE == nread) { if(QUICHE_ERR_DONE == nread) {
DEBUGF(LOG_CF(r->data, r->cf, "ingress, quiche is DONE")); CURL_TRC_CF(r->data, r->cf, "ingress, quiche is DONE");
return CURLE_OK; return CURLE_OK;
} }
else if(QUICHE_ERR_TLS_FAIL == nread) { else if(QUICHE_ERR_TLS_FAIL == nread) {
@ -650,8 +646,8 @@ static CURLcode recv_pkt(const unsigned char *pkt, size_t pktlen,
} }
} }
else if((size_t)nread < pktlen) { else if((size_t)nread < pktlen) {
DEBUGF(LOG_CF(r->data, r->cf, "ingress, quiche only read %zd/%zu bytes", CURL_TRC_CF(r->data, r->cf, "ingress, quiche only read %zd/%zu bytes",
nread, pktlen)); nread, pktlen);
} }
return CURLE_OK; return CURLE_OK;
@ -742,9 +738,6 @@ static CURLcode cf_flush_egress(struct Curl_cfilter *cf,
/* add the next packet to send, if any, to our buffer */ /* add the next packet to send, if any, to our buffer */
nread = Curl_bufq_sipn(&ctx->q.sendbuf, 0, nread = Curl_bufq_sipn(&ctx->q.sendbuf, 0,
read_pkt_to_send, &readx, &result); read_pkt_to_send, &readx, &result);
/* DEBUGF(LOG_CF(data, cf, "sip packet(maxlen=%zu) -> %zd, %d",
(size_t)0, nread, result)); */
if(nread < 0) { if(nread < 0) {
if(result != CURLE_AGAIN) if(result != CURLE_AGAIN)
return result; return result;
@ -795,8 +788,8 @@ static ssize_t recv_closed_stream(struct Curl_cfilter *cf,
failf(data, failf(data,
"HTTP/3 stream %" PRId64 " reset by server", stream->id); "HTTP/3 stream %" PRId64 " reset by server", stream->id);
*err = stream->resp_got_header? CURLE_PARTIAL_FILE : CURLE_RECV_ERROR; *err = stream->resp_got_header? CURLE_PARTIAL_FILE : CURLE_RECV_ERROR;
DEBUGF(LOG_CF(data, cf, "[h3sid=%" PRId64 "] cf_recv, was reset -> %d", CURL_TRC_CF(data, cf, "[h3sid=%" PRId64 "] cf_recv, was reset -> %d",
stream->id, *err)); stream->id, *err);
} }
else if(!stream->resp_got_header) { else if(!stream->resp_got_header) {
failf(data, failf(data,
@ -805,14 +798,14 @@ static ssize_t recv_closed_stream(struct Curl_cfilter *cf,
stream->id); stream->id);
/* *err = CURLE_PARTIAL_FILE; */ /* *err = CURLE_PARTIAL_FILE; */
*err = CURLE_RECV_ERROR; *err = CURLE_RECV_ERROR;
DEBUGF(LOG_CF(data, cf, "[h3sid=%" PRId64 "] cf_recv, closed incomplete" CURL_TRC_CF(data, cf, "[h3sid=%" PRId64 "] cf_recv, closed incomplete"
" -> %d", stream->id, *err)); " -> %d", stream->id, *err);
} }
else { else {
*err = CURLE_OK; *err = CURLE_OK;
nread = 0; nread = 0;
DEBUGF(LOG_CF(data, cf, "[h3sid=%" PRId64 "] cf_recv, closed ok" CURL_TRC_CF(data, cf, "[h3sid=%" PRId64 "] cf_recv, closed ok"
" -> %d", stream->id, *err)); " -> %d", stream->id, *err);
} }
return nread; return nread;
} }
@ -833,14 +826,14 @@ static ssize_t cf_quiche_recv(struct Curl_cfilter *cf, struct Curl_easy *data,
if(!Curl_bufq_is_empty(&stream->recvbuf)) { if(!Curl_bufq_is_empty(&stream->recvbuf)) {
nread = Curl_bufq_read(&stream->recvbuf, nread = Curl_bufq_read(&stream->recvbuf,
(unsigned char *)buf, len, err); (unsigned char *)buf, len, err);
DEBUGF(LOG_CF(data, cf, "[h3sid=%" PRId64 "] read recvbuf(len=%zu) " CURL_TRC_CF(data, cf, "[h3sid=%" PRId64 "] read recvbuf(len=%zu) "
"-> %zd, %d", stream->id, len, nread, *err)); "-> %zd, %d", stream->id, len, nread, *err);
if(nread < 0) if(nread < 0)
goto out; goto out;
} }
if(cf_process_ingress(cf, data)) { if(cf_process_ingress(cf, data)) {
DEBUGF(LOG_CF(data, cf, "cf_recv, error on ingress")); CURL_TRC_CF(data, cf, "cf_recv, error on ingress");
*err = CURLE_RECV_ERROR; *err = CURLE_RECV_ERROR;
nread = -1; nread = -1;
goto out; goto out;
@ -850,8 +843,8 @@ static ssize_t cf_quiche_recv(struct Curl_cfilter *cf, struct Curl_easy *data,
if(nread < 0 && !Curl_bufq_is_empty(&stream->recvbuf)) { if(nread < 0 && !Curl_bufq_is_empty(&stream->recvbuf)) {
nread = Curl_bufq_read(&stream->recvbuf, nread = Curl_bufq_read(&stream->recvbuf,
(unsigned char *)buf, len, err); (unsigned char *)buf, len, err);
DEBUGF(LOG_CF(data, cf, "[h3sid=%" PRId64 "] read recvbuf(len=%zu) " CURL_TRC_CF(data, cf, "[h3sid=%" PRId64 "] read recvbuf(len=%zu) "
"-> %zd, %d", stream->id, len, nread, *err)); "-> %zd, %d", stream->id, len, nread, *err);
if(nread < 0) if(nread < 0)
goto out; goto out;
} }
@ -878,16 +871,16 @@ static ssize_t cf_quiche_recv(struct Curl_cfilter *cf, struct Curl_easy *data,
out: out:
result = cf_flush_egress(cf, data); result = cf_flush_egress(cf, data);
if(result) { if(result) {
DEBUGF(LOG_CF(data, cf, "cf_recv, flush egress failed")); CURL_TRC_CF(data, cf, "cf_recv, flush egress failed");
*err = result; *err = result;
nread = -1; nread = -1;
} }
if(nread > 0) if(nread > 0)
ctx->data_recvd += nread; ctx->data_recvd += nread;
DEBUGF(LOG_CF(data, cf, "[h3sid=%"PRId64"] cf_recv(total=%" CURL_TRC_CF(data, cf, "[h3sid=%"PRId64"] cf_recv(total=%"
CURL_FORMAT_CURL_OFF_T ") -> %zd, %d", CURL_FORMAT_CURL_OFF_T ") -> %zd, %d",
stream ? stream->id : (int64_t)0, stream ? stream->id : (int64_t)0,
ctx->data_recvd, nread, *err)); ctx->data_recvd, nread, *err);
return nread; return nread;
} }
@ -975,16 +968,16 @@ static ssize_t h3_open_stream(struct Curl_cfilter *cf,
if(QUICHE_H3_ERR_STREAM_BLOCKED == stream3_id) { if(QUICHE_H3_ERR_STREAM_BLOCKED == stream3_id) {
/* quiche seems to report this error if the connection window is /* quiche seems to report this error if the connection window is
* exhausted. Which happens frequently and intermittent. */ * exhausted. Which happens frequently and intermittent. */
DEBUGF(LOG_CF(data, cf, "send_request(%s) rejected with BLOCKED", CURL_TRC_CF(data, cf, "send_request(%s) rejected with BLOCKED",
data->state.url)); data->state.url);
stream_send_suspend(cf, data); stream_send_suspend(cf, data);
*err = CURLE_AGAIN; *err = CURLE_AGAIN;
nwritten = -1; nwritten = -1;
goto out; goto out;
} }
else { else {
DEBUGF(LOG_CF(data, cf, "send_request(%s) -> %" PRId64, CURL_TRC_CF(data, cf, "send_request(%s) -> %" PRId64,
data->state.url, stream3_id)); data->state.url, stream3_id);
} }
*err = CURLE_SEND_ERROR; *err = CURLE_SEND_ERROR;
nwritten = -1; nwritten = -1;
@ -998,8 +991,8 @@ static ssize_t h3_open_stream(struct Curl_cfilter *cf,
stream->reset = FALSE; stream->reset = FALSE;
infof(data, "Using HTTP/3 Stream ID: %" PRId64, stream3_id); infof(data, "Using HTTP/3 Stream ID: %" PRId64, stream3_id);
DEBUGF(LOG_CF(data, cf, "[h3sid=%" PRId64 "] opened for %s", CURL_TRC_CF(data, cf, "[h3sid=%" PRId64 "] opened for %s",
stream3_id, data->state.url)); stream3_id, data->state.url);
out: out:
free(nva); free(nva);
@ -1037,8 +1030,8 @@ static ssize_t cf_quiche_send(struct Curl_cfilter *cf, struct Curl_easy *data,
/* TODO: we seem to be blocked on flow control and should HOLD /* TODO: we seem to be blocked on flow control and should HOLD
* sending. But when do we open again? */ * sending. But when do we open again? */
if(!quiche_conn_stream_writable(ctx->qconn, stream->id, len)) { if(!quiche_conn_stream_writable(ctx->qconn, stream->id, len)) {
DEBUGF(LOG_CF(data, cf, "[h3sid=%" PRId64 "] send_body(len=%zu) " CURL_TRC_CF(data, cf, "[h3sid=%" PRId64 "] send_body(len=%zu) "
"-> window exhausted", stream->id, len)); "-> window exhausted", stream->id, len);
stream_send_suspend(cf, data); stream_send_suspend(cf, data);
} }
*err = CURLE_AGAIN; *err = CURLE_AGAIN;
@ -1046,15 +1039,15 @@ static ssize_t cf_quiche_send(struct Curl_cfilter *cf, struct Curl_easy *data,
goto out; goto out;
} }
else if(nwritten == QUICHE_H3_TRANSPORT_ERR_FINAL_SIZE) { else if(nwritten == QUICHE_H3_TRANSPORT_ERR_FINAL_SIZE) {
DEBUGF(LOG_CF(data, cf, "[h3sid=%" PRId64 "] send_body(len=%zu) " CURL_TRC_CF(data, cf, "[h3sid=%" PRId64 "] send_body(len=%zu) "
"-> exceeds size", stream->id, len)); "-> exceeds size", stream->id, len);
*err = CURLE_SEND_ERROR; *err = CURLE_SEND_ERROR;
nwritten = -1; nwritten = -1;
goto out; goto out;
} }
else if(nwritten < 0) { else if(nwritten < 0) {
DEBUGF(LOG_CF(data, cf, "[h3sid=%" PRId64 "] send_body(len=%zu) " CURL_TRC_CF(data, cf, "[h3sid=%" PRId64 "] send_body(len=%zu) "
"-> quiche err %zd", stream->id, len, nwritten)); "-> quiche err %zd", stream->id, len, nwritten);
*err = CURLE_SEND_ERROR; *err = CURLE_SEND_ERROR;
nwritten = -1; nwritten = -1;
goto out; goto out;
@ -1068,9 +1061,9 @@ static ssize_t cf_quiche_send(struct Curl_cfilter *cf, struct Curl_easy *data,
if(stream->upload_left == 0) if(stream->upload_left == 0)
stream->send_closed = TRUE; stream->send_closed = TRUE;
DEBUGF(LOG_CF(data, cf, "[h3sid=%" PRId64 "] send body(len=%zu, " CURL_TRC_CF(data, cf, "[h3sid=%" PRId64 "] send body(len=%zu, "
"left=%" CURL_FORMAT_CURL_OFF_T ") -> %zd", "left=%" CURL_FORMAT_CURL_OFF_T ") -> %zd",
stream->id, len, stream->upload_left, nwritten)); stream->id, len, stream->upload_left, nwritten);
*err = CURLE_OK; *err = CURLE_OK;
} }
} }
@ -1081,8 +1074,8 @@ out:
*err = result; *err = result;
nwritten = -1; nwritten = -1;
} }
DEBUGF(LOG_CF(data, cf, "[h3sid=%" PRId64 "] cf_send(len=%zu) -> %zd, %d", CURL_TRC_CF(data, cf, "[h3sid=%" PRId64 "] cf_send(len=%zu) -> %zd, %d",
stream? stream->id : -1, len, nwritten, *err)); stream? stream->id : -1, len, nwritten, *err);
return nwritten; return nwritten;
} }
@ -1171,15 +1164,15 @@ static CURLcode cf_quiche_data_event(struct Curl_cfilter *cf,
stream->upload_left = 0; stream->upload_left = 0;
body[0] = 'X'; body[0] = 'X';
sent = cf_quiche_send(cf, data, body, 0, &result); sent = cf_quiche_send(cf, data, body, 0, &result);
DEBUGF(LOG_CF(data, cf, "[h3sid=%"PRId64"] DONE_SEND -> %zd, %d", CURL_TRC_CF(data, cf, "[h3sid=%"PRId64"] DONE_SEND -> %zd, %d",
stream->id, sent, result)); stream->id, sent, result);
} }
break; break;
} }
case CF_CTRL_DATA_IDLE: case CF_CTRL_DATA_IDLE:
result = cf_flush_egress(cf, data); result = cf_flush_egress(cf, data);
if(result) if(result)
DEBUGF(LOG_CF(data, cf, "data idle, flush egress -> %d", result)); CURL_TRC_CF(data, cf, "data idle, flush egress -> %d", result);
break; break;
default: default:
break; break;
@ -1210,7 +1203,7 @@ static CURLcode cf_verify_peer(struct Curl_cfilter *cf,
goto out; goto out;
} }
else else
DEBUGF(LOG_CF(data, cf, "Skipped certificate verification")); CURL_TRC_CF(data, cf, "Skipped certificate verification");
ctx->h3config = quiche_h3_config_new(); ctx->h3config = quiche_h3_config_new();
if(!ctx->h3config) { if(!ctx->h3config) {
@ -1357,8 +1350,8 @@ static CURLcode cf_connect_start(struct Curl_cfilter *cf,
offset += 1 + alpn_len; offset += 1 + alpn_len;
} }
DEBUGF(LOG_CF(data, cf, "Sent QUIC client Initial, ALPN: %s", CURL_TRC_CF(data, cf, "Sent QUIC client Initial, ALPN: %s",
alpn_protocols + 1)); alpn_protocols + 1);
} }
return CURLE_OK; return CURLE_OK;
@ -1389,7 +1382,7 @@ static CURLcode cf_quiche_connect(struct Curl_cfilter *cf,
if(ctx->reconnect_at.tv_sec && Curl_timediff(now, ctx->reconnect_at) < 0) { if(ctx->reconnect_at.tv_sec && Curl_timediff(now, ctx->reconnect_at) < 0) {
/* Not time yet to attempt the next connect */ /* Not time yet to attempt the next connect */
DEBUGF(LOG_CF(data, cf, "waiting for reconnect time")); CURL_TRC_CF(data, cf, "waiting for reconnect time");
goto out; goto out;
} }
@ -1412,12 +1405,12 @@ static CURLcode cf_quiche_connect(struct Curl_cfilter *cf,
goto out; goto out;
if(quiche_conn_is_established(ctx->qconn)) { if(quiche_conn_is_established(ctx->qconn)) {
DEBUGF(LOG_CF(data, cf, "handshake complete after %dms", CURL_TRC_CF(data, cf, "handshake complete after %dms",
(int)Curl_timediff(now, ctx->started_at))); (int)Curl_timediff(now, ctx->started_at));
ctx->handshake_at = now; ctx->handshake_at = now;
result = cf_verify_peer(cf, data); result = cf_verify_peer(cf, data);
if(!result) { if(!result) {
DEBUGF(LOG_CF(data, cf, "peer verified")); CURL_TRC_CF(data, cf, "peer verified");
cf->connected = TRUE; cf->connected = TRUE;
cf->conn->alpn = CURL_HTTP_VERSION_3; cf->conn->alpn = CURL_HTTP_VERSION_3;
*done = TRUE; *done = TRUE;
@ -1436,8 +1429,8 @@ static CURLcode cf_quiche_connect(struct Curl_cfilter *cf,
*/ */
int reconn_delay_ms = 200; int reconn_delay_ms = 200;
DEBUGF(LOG_CF(data, cf, "connect, remote closed, reconnect after %dms", CURL_TRC_CF(data, cf, "connect, remote closed, reconnect after %dms",
reconn_delay_ms)); reconn_delay_ms);
Curl_conn_cf_close(cf->next, data); Curl_conn_cf_close(cf->next, data);
cf_quiche_ctx_clear(ctx); cf_quiche_ctx_clear(ctx);
result = Curl_conn_cf_connect(cf->next, data, FALSE, done); result = Curl_conn_cf_connect(cf->next, data, FALSE, done);
@ -1503,7 +1496,7 @@ static CURLcode cf_quiche_query(struct Curl_cfilter *cf,
max_streams += quiche_conn_peer_streams_left_bidi(ctx->qconn); max_streams += quiche_conn_peer_streams_left_bidi(ctx->qconn);
} }
*pres1 = (max_streams > INT_MAX)? INT_MAX : (int)max_streams; *pres1 = (max_streams > INT_MAX)? INT_MAX : (int)max_streams;
DEBUGF(LOG_CF(data, cf, "query: MAX_CONCURRENT -> %d", *pres1)); CURL_TRC_CF(data, cf, "query: MAX_CONCURRENT -> %d", *pres1);
return CURLE_OK; return CURLE_OK;
} }
case CF_QUERY_CONNECT_REPLY_MS: case CF_QUERY_CONNECT_REPLY_MS:

30
lib/vquic/vquic.c
View File

@ -43,7 +43,7 @@
#include "bufq.h" #include "bufq.h"
#include "dynbuf.h" #include "dynbuf.h"
#include "cfilters.h" #include "cfilters.h"
#include "curl_log.h" #include "curl_trc.h"
#include "curl_msh3.h" #include "curl_msh3.h"
#include "curl_ngtcp2.h" #include "curl_ngtcp2.h"
#include "curl_quiche.h" #include "curl_quiche.h"
@ -253,11 +253,9 @@ CURLcode vquic_flush(struct Curl_cfilter *cf, struct Curl_easy *data,
blen = qctx->split_len; blen = qctx->split_len;
} }
DEBUGF(LOG_CF(data, cf, "vquic_send(len=%zu, gso=%zu)",
blen, gsolen));
result = vquic_send_packets(cf, data, qctx, buf, blen, gsolen, &sent); result = vquic_send_packets(cf, data, qctx, buf, blen, gsolen, &sent);
DEBUGF(LOG_CF(data, cf, "vquic_send(len=%zu, gso=%zu) -> %d, sent=%zu", CURL_TRC_CF(data, cf, "vquic_send(len=%zu, gso=%zu) -> %d, sent=%zu",
blen, gsolen, result, sent)); blen, gsolen, result, sent);
if(result) { if(result) {
if(result == CURLE_AGAIN) { if(result == CURLE_AGAIN) {
Curl_bufq_skip(&qctx->sendbuf, sent); Curl_bufq_skip(&qctx->sendbuf, sent);
@ -288,9 +286,9 @@ CURLcode vquic_send_tail_split(struct Curl_cfilter *cf, struct Curl_easy *data,
qctx->split_len = Curl_bufq_len(&qctx->sendbuf) - tail_len; qctx->split_len = Curl_bufq_len(&qctx->sendbuf) - tail_len;
qctx->split_gsolen = gsolen; qctx->split_gsolen = gsolen;
qctx->gsolen = tail_gsolen; qctx->gsolen = tail_gsolen;
DEBUGF(LOG_CF(data, cf, "vquic_send_tail_split: [%zu gso=%zu][%zu gso=%zu]", CURL_TRC_CF(data, cf, "vquic_send_tail_split: [%zu gso=%zu][%zu gso=%zu]",
qctx->split_len, qctx->split_gsolen, qctx->split_len, qctx->split_gsolen,
tail_len, qctx->gsolen)); tail_len, qctx->gsolen);
return vquic_flush(cf, data, qctx); return vquic_flush(cf, data, qctx);
} }
@ -330,7 +328,7 @@ static CURLcode recvmmsg_packets(struct Curl_cfilter *cf,
; ;
if(mcount == -1) { if(mcount == -1) {
if(SOCKERRNO == EAGAIN || SOCKERRNO == EWOULDBLOCK) { if(SOCKERRNO == EAGAIN || SOCKERRNO == EWOULDBLOCK) {
DEBUGF(LOG_CF(data, cf, "ingress, recvmmsg -> EAGAIN")); CURL_TRC_CF(data, cf, "ingress, recvmmsg -> EAGAIN");
goto out; goto out;
} }
if(!cf->connected && SOCKERRNO == ECONNREFUSED) { if(!cf->connected && SOCKERRNO == ECONNREFUSED) {
@ -349,7 +347,7 @@ static CURLcode recvmmsg_packets(struct Curl_cfilter *cf,
goto out; goto out;
} }
DEBUGF(LOG_CF(data, cf, "recvmmsg() -> %d packets", mcount)); CURL_TRC_CF(data, cf, "recvmmsg() -> %d packets", mcount);
pkts += mcount; pkts += mcount;
for(i = 0; i < mcount; ++i) { for(i = 0; i < mcount; ++i) {
total_nread += mmsg[i].msg_len; total_nread += mmsg[i].msg_len;
@ -362,8 +360,8 @@ static CURLcode recvmmsg_packets(struct Curl_cfilter *cf,
} }
out: out:
DEBUGF(LOG_CF(data, cf, "recvd %zu packets with %zu bytes -> %d", CURL_TRC_CF(data, cf, "recvd %zu packets with %zu bytes -> %d",
pkts, total_nread, result)); pkts, total_nread, result);
return result; return result;
} }
@ -425,8 +423,8 @@ static CURLcode recvmsg_packets(struct Curl_cfilter *cf,
} }
out: out:
DEBUGF(LOG_CF(data, cf, "recvd %zu packets with %zu bytes -> %d", CURL_TRC_CF(data, cf, "recvd %zu packets with %zu bytes -> %d",
pkts, total_nread, result)); pkts, total_nread, result);
return result; return result;
} }
@ -454,7 +452,7 @@ static CURLcode recvfrom_packets(struct Curl_cfilter *cf,
; ;
if(nread == -1) { if(nread == -1) {
if(SOCKERRNO == EAGAIN || SOCKERRNO == EWOULDBLOCK) { if(SOCKERRNO == EAGAIN || SOCKERRNO == EWOULDBLOCK) {
DEBUGF(LOG_CF(data, cf, "ingress, recvfrom -> EAGAIN")); CURL_TRC_CF(data, cf, "ingress, recvfrom -> EAGAIN");
goto out; goto out;
} }
if(!cf->connected && SOCKERRNO == ECONNREFUSED) { if(!cf->connected && SOCKERRNO == ECONNREFUSED) {
@ -482,8 +480,8 @@ static CURLcode recvfrom_packets(struct Curl_cfilter *cf,
} }
out: out:
DEBUGF(LOG_CF(data, cf, "recvd %zu packets with %zu bytes -> %d", CURL_TRC_CF(data, cf, "recvd %zu packets with %zu bytes -> %d",
pkts, total_nread, result)); pkts, total_nread, result);
return result; return result;
} }
#endif /* !HAVE_SENDMMSG && !HAVE_SENDMSG */ #endif /* !HAVE_SENDMMSG && !HAVE_SENDMSG */

7
lib/vssh/libssh2.c
View File

@ -2534,7 +2534,8 @@ static CURLcode ssh_statemach_act(struct Curl_easy *data, bool *block)
if(from > size) { if(from > size) {
failf(data, "Offset (%" failf(data, "Offset (%"
CURL_FORMAT_CURL_OFF_T ") was beyond file size (%" CURL_FORMAT_CURL_OFF_T ") was beyond file size (%"
CURL_FORMAT_CURL_OFF_T ")", from, attrs.filesize); CURL_FORMAT_CURL_OFF_T ")", from,
(curl_off_t)attrs.filesize);
return CURLE_BAD_DOWNLOAD_RESUME; return CURLE_BAD_DOWNLOAD_RESUME;
} }
if(from > to) { if(from > to) {
@ -2560,7 +2561,7 @@ static CURLcode ssh_statemach_act(struct Curl_easy *data, bool *block)
failf(data, "Offset (%" failf(data, "Offset (%"
CURL_FORMAT_CURL_OFF_T ") was beyond file size (%" CURL_FORMAT_CURL_OFF_T ") was beyond file size (%"
CURL_FORMAT_CURL_OFF_T ")", CURL_FORMAT_CURL_OFF_T ")",
data->state.resume_from, attrs.filesize); data->state.resume_from, (curl_off_t)attrs.filesize);
return CURLE_BAD_DOWNLOAD_RESUME; return CURLE_BAD_DOWNLOAD_RESUME;
} }
/* download from where? */ /* download from where? */
@ -2570,7 +2571,7 @@ static CURLcode ssh_statemach_act(struct Curl_easy *data, bool *block)
if((curl_off_t)attrs.filesize < data->state.resume_from) { if((curl_off_t)attrs.filesize < data->state.resume_from) {
failf(data, "Offset (%" CURL_FORMAT_CURL_OFF_T failf(data, "Offset (%" CURL_FORMAT_CURL_OFF_T
") was beyond file size (%" CURL_FORMAT_CURL_OFF_T ")", ") was beyond file size (%" CURL_FORMAT_CURL_OFF_T ")",
data->state.resume_from, attrs.filesize); data->state.resume_from, (curl_off_t)attrs.filesize);
return CURLE_BAD_DOWNLOAD_RESUME; return CURLE_BAD_DOWNLOAD_RESUME;
} }
} }

8
lib/vtls/mbedtls.c
View File

@ -165,8 +165,8 @@ static int bio_cf_write(void *bio, const unsigned char *buf, size_t blen)
DEBUGASSERT(data); DEBUGASSERT(data);
nwritten = Curl_conn_cf_send(cf->next, data, (char *)buf, blen, &result); nwritten = Curl_conn_cf_send(cf->next, data, (char *)buf, blen, &result);
DEBUGF(LOG_CF(data, cf, "bio_cf_out_write(len=%zu) -> %zd, err=%d", CURL_TRC_CF(data, cf, "bio_cf_out_write(len=%zu) -> %zd, err=%d",
blen, nwritten, result)); blen, nwritten, result);
if(nwritten < 0 && CURLE_AGAIN == result) { if(nwritten < 0 && CURLE_AGAIN == result) {
nwritten = MBEDTLS_ERR_SSL_WANT_WRITE; nwritten = MBEDTLS_ERR_SSL_WANT_WRITE;
} }
@ -186,8 +186,8 @@ static int bio_cf_read(void *bio, unsigned char *buf, size_t blen)
return 0; return 0;
nread = Curl_conn_cf_recv(cf->next, data, (char *)buf, blen, &result); nread = Curl_conn_cf_recv(cf->next, data, (char *)buf, blen, &result);
DEBUGF(LOG_CF(data, cf, "bio_cf_in_read(len=%zu) -> %zd, err=%d", CURL_TRC_CF(data, cf, "bio_cf_in_read(len=%zu) -> %zd, err=%d",
blen, nread, result)); blen, nread, result);
if(nread < 0 && CURLE_AGAIN == result) { if(nread < 0 && CURLE_AGAIN == result) {
nread = MBEDTLS_ERR_SSL_WANT_READ; nread = MBEDTLS_ERR_SSL_WANT_READ;
} }

8
lib/vtls/openssl.c
View File

@ -722,8 +722,8 @@ static int bio_cf_out_write(BIO *bio, const char *buf, int blen)
DEBUGASSERT(data); DEBUGASSERT(data);
nwritten = Curl_conn_cf_send(cf->next, data, buf, blen, &result); nwritten = Curl_conn_cf_send(cf->next, data, buf, blen, &result);
DEBUGF(LOG_CF(data, cf, "bio_cf_out_write(len=%d) -> %d, err=%d", CURL_TRC_CF(data, cf, "bio_cf_out_write(len=%d) -> %d, err=%d",
blen, (int)nwritten, result)); blen, (int)nwritten, result);
BIO_clear_retry_flags(bio); BIO_clear_retry_flags(bio);
backend->io_result = result; backend->io_result = result;
if(nwritten < 0) { if(nwritten < 0) {
@ -749,8 +749,8 @@ static int bio_cf_in_read(BIO *bio, char *buf, int blen)
return 0; return 0;
nread = Curl_conn_cf_recv(cf->next, data, buf, blen, &result); nread = Curl_conn_cf_recv(cf->next, data, buf, blen, &result);
DEBUGF(LOG_CF(data, cf, "bio_cf_in_read(len=%d) -> %d, err=%d", CURL_TRC_CF(data, cf, "bio_cf_in_read(len=%d) -> %d, err=%d",
blen, (int)nread, result)); blen, (int)nread, result);
BIO_clear_retry_flags(bio); BIO_clear_retry_flags(bio);
backend->io_result = result; backend->io_result = result;
if(nread < 0) { if(nread < 0) {

18
lib/vtls/rustls.c
View File

@ -104,10 +104,6 @@ read_cb(void *userdata, uint8_t *buf, uintptr_t len, uintptr_t *out_n)
ret = EINVAL; ret = EINVAL;
} }
*out_n = (int)nread; *out_n = (int)nread;
/*
DEBUGF(LOG_CF(io_ctx->data, io_ctx->cf, "cf->next recv(len=%zu) -> %zd, %d",
len, nread, result));
*/
return ret; return ret;
} }
@ -128,7 +124,7 @@ write_cb(void *userdata, const uint8_t *buf, uintptr_t len, uintptr_t *out_n)
} }
*out_n = (int)nwritten; *out_n = (int)nwritten;
/* /*
DEBUGF(LOG_CF(io_ctx->data, io_ctx->cf, "cf->next send(len=%zu) -> %zd, %d", CURL_TRC_CFX(io_ctx->data, io_ctx->cf, "cf->next send(len=%zu) -> %zd, %d",
len, nwritten, result)); len, nwritten, result));
*/ */
return ret; return ret;
@ -267,8 +263,8 @@ cr_recv(struct Curl_cfilter *cf, struct Curl_easy *data,
} }
out: out:
DEBUGF(LOG_CF(data, cf, "cf_recv(len=%zu) -> %zd, %d", CURL_TRC_CF(data, cf, "cf_recv(len=%zu) -> %zd, %d",
plainlen, nread, *err)); plainlen, nread, *err);
return nread; return nread;
} }
@ -302,7 +298,7 @@ cr_send(struct Curl_cfilter *cf, struct Curl_easy *data,
DEBUGASSERT(backend); DEBUGASSERT(backend);
rconn = backend->conn; rconn = backend->conn;
DEBUGF(LOG_CF(data, cf, "cf_send: %ld plain bytes", plainlen)); CURL_TRC_CF(data, cf, "cf_send: %ld plain bytes", plainlen);
io_ctx.cf = cf; io_ctx.cf = cf;
io_ctx.data = data; io_ctx.data = data;
@ -327,8 +323,8 @@ cr_send(struct Curl_cfilter *cf, struct Curl_easy *data,
io_error = rustls_connection_write_tls(rconn, write_cb, &io_ctx, io_error = rustls_connection_write_tls(rconn, write_cb, &io_ctx,
&tlswritten); &tlswritten);
if(io_error == EAGAIN || io_error == EWOULDBLOCK) { if(io_error == EAGAIN || io_error == EWOULDBLOCK) {
DEBUGF(LOG_CF(data, cf, "cf_send: EAGAIN after %zu bytes", CURL_TRC_CF(data, cf, "cf_send: EAGAIN after %zu bytes",
tlswritten_total)); tlswritten_total);
*err = CURLE_AGAIN; *err = CURLE_AGAIN;
return -1; return -1;
} }
@ -344,7 +340,7 @@ cr_send(struct Curl_cfilter *cf, struct Curl_easy *data,
*err = CURLE_WRITE_ERROR; *err = CURLE_WRITE_ERROR;
return -1; return -1;
} }
DEBUGF(LOG_CF(data, cf, "cf_send: wrote %zu TLS bytes", tlswritten)); CURL_TRC_CF(data, cf, "cf_send: wrote %zu TLS bytes", tlswritten);
tlswritten_total += tlswritten; tlswritten_total += tlswritten;
} }

40
lib/vtls/sectransp.c
View File

@ -845,8 +845,8 @@ static OSStatus bio_cf_in_read(SSLConnectionRef connection,
DEBUGASSERT(data); DEBUGASSERT(data);
nread = Curl_conn_cf_recv(cf->next, data, buf, *dataLength, &result); nread = Curl_conn_cf_recv(cf->next, data, buf, *dataLength, &result);
DEBUGF(LOG_CF(data, cf, "bio_read(len=%zu) -> %zd, result=%d", CURL_TRC_CF(data, cf, "bio_read(len=%zu) -> %zd, result=%d",
*dataLength, nread, result)); *dataLength, nread, result);
if(nread < 0) { if(nread < 0) {
switch(result) { switch(result) {
case CURLE_OK: case CURLE_OK:
@ -885,8 +885,8 @@ static OSStatus bio_cf_out_write(SSLConnectionRef connection,
DEBUGASSERT(data); DEBUGASSERT(data);
nwritten = Curl_conn_cf_send(cf->next, data, buf, *dataLength, &result); nwritten = Curl_conn_cf_send(cf->next, data, buf, *dataLength, &result);
DEBUGF(LOG_CF(data, cf, "bio_send(len=%zu) -> %zd, result=%d", CURL_TRC_CF(data, cf, "bio_send(len=%zu) -> %zd, result=%d",
*dataLength, nwritten, result)); *dataLength, nwritten, result);
if(nwritten <= 0) { if(nwritten <= 0) {
if(result == CURLE_AGAIN) { if(result == CURLE_AGAIN) {
rtn = errSSLWouldBlock; rtn = errSSLWouldBlock;
@ -1612,7 +1612,7 @@ static CURLcode sectransp_set_selected_ciphers(struct Curl_easy *data,
The message is a bit cryptic and longer than necessary but can be The message is a bit cryptic and longer than necessary but can be
understood by humans. */ understood by humans. */
failf(data, "SSL: cipher string \"%s\" contains unsupported cipher name" failf(data, "SSL: cipher string \"%s\" contains unsupported cipher name"
" starting position %d and ending position %d", " starting position %zd and ending position %zd",
ciphers, ciphers,
cipher_start - ciphers, cipher_start - ciphers,
cipher_end - ciphers); cipher_end - ciphers);
@ -1663,7 +1663,7 @@ static CURLcode sectransp_connect_step1(struct Curl_cfilter *cf,
DEBUGASSERT(backend); DEBUGASSERT(backend);
DEBUGF(LOG_CF(data, cf, "connect_step1")); CURL_TRC_CF(data, cf, "connect_step1");
GetDarwinVersionNumber(&darwinver_maj, &darwinver_min); GetDarwinVersionNumber(&darwinver_maj, &darwinver_min);
#endif /* CURL_BUILD_MAC */ #endif /* CURL_BUILD_MAC */
@ -2294,7 +2294,7 @@ static CURLcode verify_cert_buf(struct Curl_cfilter *cf,
/* This is not a PEM file, probably a certificate in DER format. */ /* This is not a PEM file, probably a certificate in DER format. */
rc = append_cert_to_array(data, certbuf, buflen, array); rc = append_cert_to_array(data, certbuf, buflen, array);
if(rc != CURLE_OK) { if(rc != CURLE_OK) {
DEBUGF(LOG_CF(data, cf, "append_cert for CA failed")); CURL_TRC_CF(data, cf, "append_cert for CA failed");
result = rc; result = rc;
goto out; goto out;
} }
@ -2308,7 +2308,7 @@ static CURLcode verify_cert_buf(struct Curl_cfilter *cf,
rc = append_cert_to_array(data, der, derlen, array); rc = append_cert_to_array(data, der, derlen, array);
free(der); free(der);
if(rc != CURLE_OK) { if(rc != CURLE_OK) {
DEBUGF(LOG_CF(data, cf, "append_cert for CA failed")); CURL_TRC_CF(data, cf, "append_cert for CA failed");
result = rc; result = rc;
goto out; goto out;
} }
@ -2324,7 +2324,7 @@ static CURLcode verify_cert_buf(struct Curl_cfilter *cf,
goto out; goto out;
} }
DEBUGF(LOG_CF(data, cf, "setting %d trust anchors", n)); CURL_TRC_CF(data, cf, "setting %d trust anchors", n);
ret = SecTrustSetAnchorCertificates(trust, array); ret = SecTrustSetAnchorCertificates(trust, array);
if(ret != noErr) { if(ret != noErr) {
failf(data, "SecTrustSetAnchorCertificates() returned error %d", ret); failf(data, "SecTrustSetAnchorCertificates() returned error %d", ret);
@ -2346,11 +2346,11 @@ static CURLcode verify_cert_buf(struct Curl_cfilter *cf,
switch(trust_eval) { switch(trust_eval) {
case kSecTrustResultUnspecified: case kSecTrustResultUnspecified:
/* what does this really mean? */ /* what does this really mean? */
DEBUGF(LOG_CF(data, cf, "trust result: Unspecified")); CURL_TRC_CF(data, cf, "trust result: Unspecified");
result = CURLE_OK; result = CURLE_OK;
goto out; goto out;
case kSecTrustResultProceed: case kSecTrustResultProceed:
DEBUGF(LOG_CF(data, cf, "trust result: Proceed")); CURL_TRC_CF(data, cf, "trust result: Proceed");
result = CURLE_OK; result = CURLE_OK;
goto out; goto out;
@ -2383,7 +2383,7 @@ static CURLcode verify_cert(struct Curl_cfilter *cf,
size_t buflen; size_t buflen;
if(ca_info_blob) { if(ca_info_blob) {
DEBUGF(LOG_CF(data, cf, "verify_peer, CA from config blob")); CURL_TRC_CF(data, cf, "verify_peer, CA from config blob");
certbuf = (unsigned char *)malloc(ca_info_blob->len + 1); certbuf = (unsigned char *)malloc(ca_info_blob->len + 1);
if(!certbuf) { if(!certbuf) {
return CURLE_OUT_OF_MEMORY; return CURLE_OUT_OF_MEMORY;
@ -2393,7 +2393,7 @@ static CURLcode verify_cert(struct Curl_cfilter *cf,
certbuf[ca_info_blob->len]='\0'; certbuf[ca_info_blob->len]='\0';
} }
else if(cafile) { else if(cafile) {
DEBUGF(LOG_CF(data, cf, "verify_peer, CA from file '%s'", cafile)); CURL_TRC_CF(data, cf, "verify_peer, CA from file '%s'", cafile);
if(read_cert(cafile, &certbuf, &buflen) < 0) { if(read_cert(cafile, &certbuf, &buflen) < 0) {
failf(data, "SSL: failed to read or invalid CA certificate"); failf(data, "SSL: failed to read or invalid CA certificate");
return CURLE_SSL_CACERT_BADFILE; return CURLE_SSL_CACERT_BADFILE;
@ -2485,7 +2485,7 @@ static CURLcode pkp_pin_peer_pubkey(struct Curl_easy *data,
spkiHeaderLength = 23; spkiHeaderLength = 23;
break; break;
default: default:
infof(data, "SSL: unhandled public key length: %d", pubkeylen); infof(data, "SSL: unhandled public key length: %zu", pubkeylen);
#elif SECTRANSP_PINNEDPUBKEY_V2 #elif SECTRANSP_PINNEDPUBKEY_V2
default: default:
/* ecDSA secp256r1 pubkeylen == 91 header already included? /* ecDSA secp256r1 pubkeylen == 91 header already included?
@ -2534,7 +2534,7 @@ static CURLcode sectransp_connect_step2(struct Curl_cfilter *cf,
|| ssl_connect_2_reading == connssl->connecting_state || ssl_connect_2_reading == connssl->connecting_state
|| ssl_connect_2_writing == connssl->connecting_state); || ssl_connect_2_writing == connssl->connecting_state);
DEBUGASSERT(backend); DEBUGASSERT(backend);
DEBUGF(LOG_CF(data, cf, "connect_step2")); CURL_TRC_CF(data, cf, "connect_step2");
/* Here goes nothing: */ /* Here goes nothing: */
check_handshake: check_handshake:
@ -3001,7 +3001,7 @@ static CURLcode sectransp_connect_step3(struct Curl_cfilter *cf,
struct ssl_connect_data *connssl = cf->ctx; struct ssl_connect_data *connssl = cf->ctx;
CURLcode result; CURLcode result;
DEBUGF(LOG_CF(data, cf, "connect_step3")); CURL_TRC_CF(data, cf, "connect_step3");
/* There is no step 3! /* There is no step 3!
* Well, okay, let's collect server certificates, and if verbose mode is on, * Well, okay, let's collect server certificates, and if verbose mode is on,
* let's print the details of the server certificates. */ * let's print the details of the server certificates. */
@ -3110,7 +3110,7 @@ sectransp_connect_common(struct Curl_cfilter *cf, struct Curl_easy *data,
} }
if(ssl_connect_done == connssl->connecting_state) { if(ssl_connect_done == connssl->connecting_state) {
DEBUGF(LOG_CF(data, cf, "connected")); CURL_TRC_CF(data, cf, "connected");
connssl->state = ssl_connection_complete; connssl->state = ssl_connection_complete;
*done = TRUE; *done = TRUE;
} }
@ -3157,7 +3157,7 @@ static void sectransp_close(struct Curl_cfilter *cf, struct Curl_easy *data)
DEBUGASSERT(backend); DEBUGASSERT(backend);
if(backend->ssl_ctx) { if(backend->ssl_ctx) {
DEBUGF(LOG_CF(data, cf, "close")); CURL_TRC_CF(data, cf, "close");
(void)SSLClose(backend->ssl_ctx); (void)SSLClose(backend->ssl_ctx);
#if CURL_BUILD_MAC_10_8 || CURL_BUILD_IOS #if CURL_BUILD_MAC_10_8 || CURL_BUILD_IOS
if(SSLCreateContext) if(SSLCreateContext)
@ -3203,7 +3203,7 @@ static int sectransp_shutdown(struct Curl_cfilter *cf,
what = SOCKET_READABLE(Curl_conn_cf_get_socket(cf, data), what = SOCKET_READABLE(Curl_conn_cf_get_socket(cf, data),
SSL_SHUTDOWN_TIMEOUT); SSL_SHUTDOWN_TIMEOUT);
DEBUGF(LOG_CF(data, cf, "shutdown")); CURL_TRC_CF(data, cf, "shutdown");
while(loop--) { while(loop--) {
if(what < 0) { if(what < 0) {
/* anything that gets here is fatally bad */ /* anything that gets here is fatally bad */
@ -3265,7 +3265,7 @@ static bool sectransp_data_pending(struct Curl_cfilter *cf,
DEBUGASSERT(backend); DEBUGASSERT(backend);
if(backend->ssl_ctx) { /* SSL is in use */ if(backend->ssl_ctx) { /* SSL is in use */
DEBUGF(LOG_CF((struct Curl_easy *)data, cf, "data_pending")); CURL_TRC_CF((struct Curl_easy *)data, cf, "data_pending");
err = SSLGetBufferedReadSize(backend->ssl_ctx, &buffer); err = SSLGetBufferedReadSize(backend->ssl_ctx, &buffer);
if(err == noErr) if(err == noErr)
return buffer > 0UL; return buffer > 0UL;

6
lib/vtls/vtls.c
View File

@ -1596,7 +1596,7 @@ static ssize_t ssl_cf_recv(struct Curl_cfilter *cf,
/* eof */ /* eof */
*err = CURLE_OK; *err = CURLE_OK;
} }
DEBUGF(LOG_CF(data, cf, "cf_recv(len=%zu) -> %zd, %d", len, nread, *err)); CURL_TRC_CF(data, cf, "cf_recv(len=%zu) -> %zd, %d", len, nread, *err);
CF_DATA_RESTORE(cf, save); CF_DATA_RESTORE(cf, save);
return nread; return nread;
} }
@ -1697,7 +1697,7 @@ static bool cf_ssl_is_alive(struct Curl_cfilter *cf, struct Curl_easy *data,
struct Curl_cftype Curl_cft_ssl = { struct Curl_cftype Curl_cft_ssl = {
"SSL", "SSL",
CF_TYPE_SSL, CF_TYPE_SSL,
CURL_LOG_DEFAULT, CURL_LOG_LVL_NONE,
ssl_cf_destroy, ssl_cf_destroy,
ssl_cf_connect, ssl_cf_connect,
ssl_cf_close, ssl_cf_close,
@ -1715,7 +1715,7 @@ struct Curl_cftype Curl_cft_ssl = {
struct Curl_cftype Curl_cft_ssl_proxy = { struct Curl_cftype Curl_cft_ssl_proxy = {
"SSL-PROXY", "SSL-PROXY",
CF_TYPE_SSL, CF_TYPE_SSL,
CURL_LOG_DEFAULT, CURL_LOG_LVL_NONE,
ssl_cf_destroy, ssl_cf_destroy,
ssl_cf_connect, ssl_cf_connect,
ssl_cf_close, ssl_cf_close,

24
lib/vtls/wolfssl.c
View File

@ -290,8 +290,8 @@ static int bio_cf_out_write(WOLFSSL_BIO *bio, const char *buf, int blen)
DEBUGASSERT(data); DEBUGASSERT(data);
nwritten = Curl_conn_cf_send(cf->next, data, buf, blen, &result); nwritten = Curl_conn_cf_send(cf->next, data, buf, blen, &result);
backend->io_result = result; backend->io_result = result;
DEBUGF(LOG_CF(data, cf, "bio_write(len=%d) -> %zd, %d", CURL_TRC_CF(data, cf, "bio_write(len=%d) -> %zd, %d",
blen, nwritten, result)); blen, nwritten, result);
wolfSSL_BIO_clear_retry_flags(bio); wolfSSL_BIO_clear_retry_flags(bio);
if(nwritten < 0 && CURLE_AGAIN == result) if(nwritten < 0 && CURLE_AGAIN == result)
BIO_set_retry_read(bio); BIO_set_retry_read(bio);
@ -315,8 +315,7 @@ static int bio_cf_in_read(WOLFSSL_BIO *bio, char *buf, int blen)
nread = Curl_conn_cf_recv(cf->next, data, buf, blen, &result); nread = Curl_conn_cf_recv(cf->next, data, buf, blen, &result);
backend->io_result = result; backend->io_result = result;
DEBUGF(LOG_CF(data, cf, "bio_read(len=%d) -> %zd, %d", CURL_TRC_CF(data, cf, "bio_read(len=%d) -> %zd, %d", blen, nread, result);
blen, nread, result));
wolfSSL_BIO_clear_retry_flags(bio); wolfSSL_BIO_clear_retry_flags(bio);
if(nread < 0 && CURLE_AGAIN == result) if(nread < 0 && CURLE_AGAIN == result)
BIO_set_retry_read(bio); BIO_set_retry_read(bio);
@ -1018,17 +1017,16 @@ static ssize_t wolfssl_send(struct Curl_cfilter *cf,
case SSL_ERROR_WANT_READ: case SSL_ERROR_WANT_READ:
case SSL_ERROR_WANT_WRITE: case SSL_ERROR_WANT_WRITE:
/* there's data pending, re-invoke SSL_write() */ /* there's data pending, re-invoke SSL_write() */
DEBUGF(LOG_CF(data, cf, "wolfssl_send(len=%zu) -> AGAIN", len)); CURL_TRC_CF(data, cf, "wolfssl_send(len=%zu) -> AGAIN", len);
*curlcode = CURLE_AGAIN; *curlcode = CURLE_AGAIN;
return -1; return -1;
default: default:
if(backend->io_result == CURLE_AGAIN) { if(backend->io_result == CURLE_AGAIN) {
DEBUGF(LOG_CF(data, cf, "wolfssl_send(len=%zu) -> AGAIN", len)); CURL_TRC_CF(data, cf, "wolfssl_send(len=%zu) -> AGAIN", len);
*curlcode = CURLE_AGAIN; *curlcode = CURLE_AGAIN;
return -1; return -1;
} }
DEBUGF(LOG_CF(data, cf, "wolfssl_send(len=%zu) -> %d, %d", CURL_TRC_CF(data, cf, "wolfssl_send(len=%zu) -> %d, %d", len, rc, err);
len, rc, err));
failf(data, "SSL write: %s, errno %d", failf(data, "SSL write: %s, errno %d",
ERR_error_string(err, error_buffer), ERR_error_string(err, error_buffer),
SOCKERRNO); SOCKERRNO);
@ -1036,7 +1034,7 @@ static ssize_t wolfssl_send(struct Curl_cfilter *cf,
return -1; return -1;
} }
} }
DEBUGF(LOG_CF(data, cf, "wolfssl_send(len=%zu) -> %d", len, rc)); CURL_TRC_CF(data, cf, "wolfssl_send(len=%zu) -> %d", len, rc);
return rc; return rc;
} }
@ -1089,7 +1087,7 @@ static ssize_t wolfssl_recv(struct Curl_cfilter *cf,
switch(err) { switch(err) {
case SSL_ERROR_ZERO_RETURN: /* no more data */ case SSL_ERROR_ZERO_RETURN: /* no more data */
DEBUGF(LOG_CF(data, cf, "wolfssl_recv(len=%zu) -> CLOSED", blen)); CURL_TRC_CF(data, cf, "wolfssl_recv(len=%zu) -> CLOSED", blen);
*curlcode = CURLE_OK; *curlcode = CURLE_OK;
return 0; return 0;
case SSL_ERROR_NONE: case SSL_ERROR_NONE:
@ -1098,12 +1096,12 @@ static ssize_t wolfssl_recv(struct Curl_cfilter *cf,
/* FALLTHROUGH */ /* FALLTHROUGH */
case SSL_ERROR_WANT_WRITE: case SSL_ERROR_WANT_WRITE:
/* there's data pending, re-invoke SSL_read() */ /* there's data pending, re-invoke SSL_read() */
DEBUGF(LOG_CF(data, cf, "wolfssl_recv(len=%zu) -> AGAIN", blen)); CURL_TRC_CF(data, cf, "wolfssl_recv(len=%zu) -> AGAIN", blen);
*curlcode = CURLE_AGAIN; *curlcode = CURLE_AGAIN;
return -1; return -1;
default: default:
if(backend->io_result == CURLE_AGAIN) { if(backend->io_result == CURLE_AGAIN) {
DEBUGF(LOG_CF(data, cf, "wolfssl_recv(len=%zu) -> AGAIN", blen)); CURL_TRC_CF(data, cf, "wolfssl_recv(len=%zu) -> AGAIN", blen);
*curlcode = CURLE_AGAIN; *curlcode = CURLE_AGAIN;
return -1; return -1;
} }
@ -1113,7 +1111,7 @@ static ssize_t wolfssl_recv(struct Curl_cfilter *cf,
return -1; return -1;
} }
} }
DEBUGF(LOG_CF(data, cf, "wolfssl_recv(len=%zu) -> %d", blen, nread)); CURL_TRC_CF(data, cf, "wolfssl_recv(len=%zu) -> %d", blen, nread);
return nread; return nread;
} }

1
libcurl.def
View File

@ -29,6 +29,7 @@ curl_global_cleanup
curl_global_init curl_global_init
curl_global_init_mem curl_global_init_mem
curl_global_sslset curl_global_sslset
curl_global_trace
curl_maprintf curl_maprintf
curl_mfprintf curl_mfprintf
curl_mime_addpart curl_mime_addpart

61
src/tool_getparam.c
View File

@ -209,6 +209,7 @@ static const struct LongShort aliases[]= {
{"$~", "happy-eyeballs-timeout-ms", ARG_STRING}, {"$~", "happy-eyeballs-timeout-ms", ARG_STRING},
{"$!", "retry-all-errors", ARG_BOOL}, {"$!", "retry-all-errors", ARG_BOOL},
{"$%", "trace-ids", ARG_BOOL}, {"$%", "trace-ids", ARG_BOOL},
{"$&", "trace-config", ARG_STRING},
{"0", "http1.0", ARG_NONE}, {"0", "http1.0", ARG_NONE},
{"01", "http1.1", ARG_NONE}, {"01", "http1.1", ARG_NONE},
{"02", "http2", ARG_NONE}, {"02", "http2", ARG_NONE},
@ -681,6 +682,61 @@ static void sethttpver(struct GlobalConfig *global,
config->httpversion = httpversion; config->httpversion = httpversion;
} }
static CURLcode set_trace_config(struct GlobalConfig *global,
const char *config)
{
CURLcode result = CURLE_OK;
char *token, *tmp, *name;
bool toggle;
tmp = strdup(config);
if(!tmp)
return CURLE_OUT_OF_MEMORY;
/* Allow strtok() here since this isn't used threaded */
/* !checksrc! disable BANNEDFUNC 2 */
token = strtok(tmp, ", ");
while(token) {
switch(*token) {
case '-':
toggle = FALSE;
name = token + 1;
break;
case '+':
toggle = TRUE;
name = token + 1;
break;
default:
toggle = TRUE;
name = token;
break;
}
if(strcasecompare(name, "all")) {
global->traceids = toggle;
global->tracetime = toggle;
result = curl_global_trace(token);
if(result)
goto out;
}
else if(strcasecompare(name, "ids")) {
global->traceids = toggle;
}
else if(strcasecompare(name, "time")) {
global->tracetime = toggle;
}
else {
result = curl_global_trace(token);
if(result)
goto out;
}
token = strtok(NULL, ", ");
}
out:
free(tmp);
return result;
}
ParameterError getparameter(const char *flag, /* f or -long-flag */ ParameterError getparameter(const char *flag, /* f or -long-flag */
char *nextarg, /* NULL if unset */ char *nextarg, /* NULL if unset */
argv_item_t cleararg, argv_item_t cleararg,
@ -1463,6 +1519,11 @@ ParameterError getparameter(const char *flag, /* f or -long-flag */
case '%': /* --trace-ids */ case '%': /* --trace-ids */
global->traceids = toggle; global->traceids = toggle;
break; break;
case '&': /* --trace-config */
if(set_trace_config(global, nextarg)) {
err = PARAM_NO_MEM;
}
break;
} }
break; break;
case '#': case '#':

3
src/tool_listhelp.c
View File

@ -759,6 +759,9 @@ const struct helptxt helptext[] = {
{" --trace-ascii <file>", {" --trace-ascii <file>",
"Like --trace, but without hex output", "Like --trace, but without hex output",
CURLHELP_VERBOSE}, CURLHELP_VERBOSE},
{" --trace-config",
"Configure which details to log in trace/verbose output",
CURLHELP_VERBOSE},
{" --trace-ids", {" --trace-ids",
"Add transfer and connection identifiers to trace/verbose output", "Add transfer and connection identifiers to trace/verbose output",
CURLHELP_VERBOSE}, CURLHELP_VERBOSE},

1
tests/data/test1135
View File

@ -55,6 +55,7 @@ curl_free
curl_global_init curl_global_init
curl_global_init_mem curl_global_init_mem
curl_global_cleanup curl_global_cleanup
curl_global_trace
curl_global_sslset curl_global_sslset
curl_slist_append curl_slist_append
curl_slist_free_all curl_slist_free_all

112
tests/http/test_15_tracing.py Normal file
View File

@ -0,0 +1,112 @@
#!/usr/bin/env python3
# -*- coding: utf-8 -*-
#***************************************************************************
# _ _ ____ _
# Project ___| | | | _ \| |
# / __| | | | |_) | |
# | (__| |_| | _ <| |___
# \___|\___/|_| \_\_____|
#
# Copyright (C) Daniel Stenberg, <daniel@haxx.se>, et al.
#
# This software is licensed as described in the file COPYING, which
# you should have received as part of this distribution. The terms
# are also available at https://curl.se/docs/copyright.html.
#
# You may opt to use, copy, modify, merge, publish, distribute and/or sell
# copies of the Software, and permit persons to whom the Software is
# furnished to do so, under the terms of the COPYING file.
#
# This software is distributed on an "AS IS" basis, WITHOUT WARRANTY OF ANY
# KIND, either express or implied.
#
# SPDX-License-Identifier: curl
#
###########################################################################
#
import logging
import re
from testenv import Env
from testenv import CurlClient
log = logging.getLogger(__name__)
class TestTracing:
# default verbose output
def test_15_01_trace_defaults(self, env: Env, httpd):
curl = CurlClient(env=env)
url = f'http://{env.domain1}:{env.http_port}/data.json'
r = curl.http_get(url=url, def_tracing=False, extra_args=[
'-v'
])
r.check_response(http_status=200)
trace = r.trace_lines
assert len(trace) > 0
# trace ids
def test_15_02_trace_ids(self, env: Env, httpd):
curl = CurlClient(env=env)
url = f'http://{env.domain1}:{env.http_port}/data.json'
r = curl.http_get(url=url, def_tracing=False, extra_args=[
'-v', '--trace-config', 'ids'
])
r.check_response(http_status=200)
for line in r.trace_lines:
m = re.match(r'^\[0-[0x]] .+', line)
if m is None:
assert False, f'no match: {line}'
# trace ids+time
def test_15_03_trace_ids_time(self, env: Env, httpd):
curl = CurlClient(env=env)
url = f'http://{env.domain1}:{env.http_port}/data.json'
r = curl.http_get(url=url, def_tracing=False, extra_args=[
'-v', '--trace-config', 'ids,time'
])
r.check_response(http_status=200)
for line in r.trace_lines:
m = re.match(r'^([0-9:.]+) \[0-[0x]] .+', line)
if m is None:
assert False, f'no match: {line}'
# trace all
def test_15_04_trace_all(self, env: Env, httpd):
curl = CurlClient(env=env)
url = f'http://{env.domain1}:{env.http_port}/data.json'
r = curl.http_get(url=url, def_tracing=False, extra_args=[
'-v', '--trace-config', 'all'
])
r.check_response(http_status=200)
found_tcp = False
for line in r.trace_lines:
m = re.match(r'^([0-9:.]+) \[0-[0x]] .+', line)
if m is None:
assert False, f'no match: {line}'
m = re.match(r'^([0-9:.]+) \[0-[0x]] . \[TCP].+', line)
if m is not None:
found_tcp = True
if not found_tcp:
assert False, f'TCP filter does not appear in trace "all": {r.stderr}'
# trace all, no TCP, no time
def test_15_05_trace_all(self, env: Env, httpd):
curl = CurlClient(env=env)
url = f'http://{env.domain1}:{env.http_port}/data.json'
r = curl.http_get(url=url, def_tracing=False, extra_args=[
'-v', '--trace-config', 'all,-tcp,-time'
])
r.check_response(http_status=200)
found_tcp = False
for line in r.trace_lines:
m = re.match(r'^\[0-[0x]] .+', line)
if m is None:
assert False, f'no match: {line}'
m = re.match(r'^\[0-[0x]] . \[TCP].+', line)
if m is not None:
found_tcp = True
if found_tcp:
assert False, f'TCP filter appears in trace "all,-tcp": {r.stderr}'

21
tests/http/testenv/curl.py
View File

@ -337,8 +337,10 @@ class CurlClient:
xargs.append('--proxytunnel') xargs.append('--proxytunnel')
return xargs return xargs
def http_get(self, url: str, extra_args: Optional[List[str]] = None): def http_get(self, url: str, extra_args: Optional[List[str]] = None,
return self._raw(url, options=extra_args, with_stats=False) def_tracing: bool = True):
return self._raw(url, options=extra_args, with_stats=False,
def_tracing=def_tracing)
def http_download(self, urls: List[str], def http_download(self, urls: List[str],
alpn_proto: Optional[str] = None, alpn_proto: Optional[str] = None,
@ -463,11 +465,13 @@ class CurlClient:
force_resolve=True, force_resolve=True,
with_stats=False, with_stats=False,
with_headers=True, with_headers=True,
with_trace=False): with_trace=False,
def_tracing=True):
args = self._complete_args( args = self._complete_args(
urls=urls, timeout=timeout, options=options, insecure=insecure, urls=urls, timeout=timeout, options=options, insecure=insecure,
alpn_proto=alpn_proto, force_resolve=force_resolve, alpn_proto=alpn_proto, force_resolve=force_resolve,
with_headers=with_headers, with_trace=with_trace) with_headers=with_headers, with_trace=with_trace,
def_tracing=def_tracing)
r = self._run(args, intext=intext, with_stats=with_stats) r = self._run(args, intext=intext, with_stats=with_stats)
if r.exit_code == 0 and with_headers: if r.exit_code == 0 and with_headers:
self._parse_headerfile(self._headerfile, r=r) self._parse_headerfile(self._headerfile, r=r)
@ -479,15 +483,20 @@ class CurlClient:
insecure=False, force_resolve=True, insecure=False, force_resolve=True,
alpn_proto: Optional[str] = None, alpn_proto: Optional[str] = None,
with_headers: bool = True, with_headers: bool = True,
with_trace: bool = False): with_trace: bool = False,
def_tracing: bool = True):
if not isinstance(urls, list): if not isinstance(urls, list):
urls = [urls] urls = [urls]
args = [self._curl, "-s", "--path-as-is", '--trace-time', '--trace-ids'] args = [self._curl, "-s", "--path-as-is"]
if def_tracing:
args.extend(['--trace-time', '--trace-ids'])
if with_headers: if with_headers:
args.extend(["-D", self._headerfile]) args.extend(["-D", self._headerfile])
if with_trace or self.env.verbose > 2: if with_trace or self.env.verbose > 2:
args.extend(['--trace', self._tracefile]) args.extend(['--trace', self._tracefile])
elif def_tracing is False:
pass
elif self.env.verbose > 1: elif self.env.verbose > 1:
args.extend(['--trace-ascii', self._tracefile]) args.extend(['--trace-ascii', self._tracefile])
elif not self._silent: elif not self._silent:

4
tests/unit/unit2600.c
View File

@ -50,7 +50,7 @@
#include "urldata.h" #include "urldata.h"
#include "connect.h" #include "connect.h"
#include "cfilters.h" #include "cfilters.h"
#include "curl_log.h" #include "curl_trc.h"
/* copied from hostip.c to switch using SIGALARM for timeouts. /* copied from hostip.c to switch using SIGALARM for timeouts.
* SIGALARM has only seconds resolution, so our tests will not work * SIGALARM has only seconds resolution, so our tests will not work
@ -164,7 +164,7 @@ static CURLcode cf_test_connect(struct Curl_cfilter *cf,
static struct Curl_cftype cft_test = { static struct Curl_cftype cft_test = {
"TEST", "TEST",
CF_TYPE_IP_CONNECT, CF_TYPE_IP_CONNECT,
CURL_LOG_DEFAULT, CURL_LOG_LVL_NONE,
cf_test_destroy, cf_test_destroy,
cf_test_connect, cf_test_connect,
Curl_cf_def_close, Curl_cf_def_close,

2
tests/unit/unit2601.c
View File

@ -25,7 +25,7 @@
#include "urldata.h" #include "urldata.h"
#include "bufq.h" #include "bufq.h"
#include "curl_log.h" #include "curl_trc.h"
static CURLcode unit_setup(void) static CURLcode unit_setup(void)
{ {

2
tests/unit/unit2602.c
View File

@ -26,7 +26,7 @@
#include "urldata.h" #include "urldata.h"
#include "dynbuf.h" #include "dynbuf.h"
#include "dynhds.h" #include "dynhds.h"
#include "curl_log.h" #include "curl_trc.h"
static CURLcode unit_setup(void) static CURLcode unit_setup(void)
{ {

2
tests/unit/unit2603.c
View File

@ -26,7 +26,7 @@
#include "urldata.h" #include "urldata.h"
#include "http.h" #include "http.h"
#include "http1.h" #include "http1.h"
#include "curl_log.h" #include "curl_trc.h"
static CURLcode unit_setup(void) static CURLcode unit_setup(void)
{ {