From e12b39e133822c6a03cffd75e102dc9f34541230 Mon Sep 17 00:00:00 2001 From: Stefan Eissing Date: Thu, 3 Aug 2023 17:32:25 +0200 Subject: [PATCH] trace: make tracing available in non-debug builds Add --trace-config to curl Add curl_global_trace() to libcurl Closes #11421 --- docs/cmdline-opts/Makefile.inc | 1 + docs/cmdline-opts/trace-config.d | 21 +++ docs/cmdline-opts/trace.d | 2 +- docs/libcurl/Makefile.inc | 1 + docs/libcurl/curl_global_trace.3 | 118 ++++++++++++++ docs/options-in-versions | 1 + include/curl/curl.h | 14 ++ lib/Makefile.inc | 4 +- lib/cf-h1-proxy.c | 34 ++-- lib/cf-h2-proxy.c | 172 ++++++++++----------- lib/cf-haproxy.c | 6 +- lib/cf-https-connect.c | 38 ++--- lib/cf-socket.c | 88 +++++------ lib/cfilters.c | 2 +- lib/connect.c | 56 +++---- lib/curl_log.h | 121 --------------- lib/{curl_log.c => curl_trc.c} | 83 ++++++---- lib/curl_trc.h | 150 ++++++++++++++++++ lib/easy.c | 19 ++- lib/http2.c | 257 +++++++++++++++---------------- lib/http_proxy.c | 12 +- lib/rand.c | 1 + lib/sendf.h | 2 +- lib/url.c | 8 +- lib/urldata.h | 12 ++ lib/vquic/curl_msh3.c | 64 ++++---- lib/vquic/curl_ngtcp2.c | 156 +++++++++---------- lib/vquic/curl_quiche.c | 163 ++++++++++---------- lib/vquic/vquic.c | 32 ++-- lib/vssh/libssh2.c | 7 +- lib/vtls/mbedtls.c | 8 +- lib/vtls/openssl.c | 8 +- lib/vtls/rustls.c | 18 +-- lib/vtls/sectransp.c | 40 ++--- lib/vtls/vtls.c | 6 +- lib/vtls/wolfssl.c | 24 ++- libcurl.def | 1 + src/tool_getparam.c | 61 ++++++++ src/tool_listhelp.c | 3 + tests/data/test1135 | 1 + tests/http/test_15_tracing.py | 112 ++++++++++++++ tests/http/testenv/curl.py | 21 ++- tests/unit/unit2600.c | 4 +- tests/unit/unit2601.c | 2 +- tests/unit/unit2602.c | 2 +- tests/unit/unit2603.c | 2 +- 46 files changed, 1167 insertions(+), 791 deletions(-) create mode 100644 docs/cmdline-opts/trace-config.d create mode 100644 docs/libcurl/curl_global_trace.3 delete mode 100644 lib/curl_log.h rename lib/{curl_log.c => curl_trc.c} (78%) create mode 100644 lib/curl_trc.h create mode 100644 tests/http/test_15_tracing.py diff --git a/docs/cmdline-opts/Makefile.inc b/docs/cmdline-opts/Makefile.inc index 6f9caea07e..fa4cbe59f0 100644 --- a/docs/cmdline-opts/Makefile.inc +++ b/docs/cmdline-opts/Makefile.inc @@ -265,6 +265,7 @@ DPAGES = \ tlsv1.d \ tr-encoding.d \ trace-ascii.d \ + trace-config.d \ trace-ids.d \ trace-time.d \ trace.d \ diff --git a/docs/cmdline-opts/trace-config.d b/docs/cmdline-opts/trace-config.d new file mode 100644 index 0000000000..636e96b0d4 --- /dev/null +++ b/docs/cmdline-opts/trace-config.d @@ -0,0 +1,21 @@ +c: Copyright (C) Daniel Stenberg, , et al. +SPDX-License-Identifier: curl +Long: trace-config +Arg: +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. diff --git a/docs/cmdline-opts/trace.d b/docs/cmdline-opts/trace.d index cc3087a8ca..97f4e2fdac 100644 --- a/docs/cmdline-opts/trace.d +++ b/docs/cmdline-opts/trace.d @@ -7,7 +7,7 @@ Mutexed: verbose trace-ascii Category: verbose Example: --trace log.txt $URL Added: 7.9.7 -See-also: trace-ascii trace-ids trace-time +See-also: trace-ascii trace-config trace-ids trace-time Multi: single Scope: global --- diff --git a/docs/libcurl/Makefile.inc b/docs/libcurl/Makefile.inc index 35122e7279..e7e8280124 100644 --- a/docs/libcurl/Makefile.inc +++ b/docs/libcurl/Makefile.inc @@ -54,6 +54,7 @@ man_MANS = \ curl_global_cleanup.3 \ curl_global_init.3 \ curl_global_init_mem.3 \ + curl_global_trace.3 \ curl_global_sslset.3 \ curl_mime_addpart.3 \ curl_mime_data.3 \ diff --git a/docs/libcurl/curl_global_trace.3 b/docs/libcurl/curl_global_trace.3 new file mode 100644 index 0000000000..b6e36abf99 --- /dev/null +++ b/docs/libcurl/curl_global_trace.3 @@ -0,0 +1,118 @@ +.\" ************************************************************************** +.\" * _ _ ____ _ +.\" * Project ___| | | | _ \| | +.\" * / __| | | | |_) | | +.\" * | (__| |_| | _ <| |___ +.\" * \___|\___/|_| \_\_____| +.\" * +.\" * Copyright (C) Daniel Stenberg, , 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 + +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) " diff --git a/docs/options-in-versions b/docs/options-in-versions index 8e6e17569a..e79a25ad25 100644 --- a/docs/options-in-versions +++ b/docs/options-in-versions @@ -252,6 +252,7 @@ --tr-encoding 7.21.6 --trace 7.9.7 --trace-ascii 7.9.7 +--trace-config 8.3.0 --trace-ids 8.2.0 --trace-time 7.14.0 --unix-socket 7.40.0 diff --git a/include/curl/curl.h b/include/curl/curl.h index ea6fcb672e..82ce1e27ef 100644 --- a/include/curl/curl.h +++ b/include/curl/curl.h @@ -2731,6 +2731,20 @@ CURL_EXTERN CURLcode curl_global_init_mem(long flags, */ 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) */ struct curl_slist { char *data; diff --git a/lib/Makefile.inc b/lib/Makefile.inc index aaf27a9091..d851f909a9 100644 --- a/lib/Makefile.inc +++ b/lib/Makefile.inc @@ -124,7 +124,6 @@ LIB_CFILES = \ curl_get_line.c \ curl_gethostname.c \ curl_gssapi.c \ - curl_log.c \ curl_memrchr.c \ curl_multibyte.c \ curl_ntlm_core.c \ @@ -135,6 +134,7 @@ LIB_CFILES = \ curl_sasl.c \ curl_sspi.c \ curl_threads.c \ + curl_trc.c \ dict.c \ doh.c \ dynbuf.c \ @@ -260,7 +260,6 @@ LIB_HFILES = \ curl_hmac.h \ curl_krb5.h \ curl_ldap.h \ - curl_log.h \ curl_md4.h \ curl_md5.h \ curl_memory.h \ @@ -278,6 +277,7 @@ LIB_HFILES = \ curl_sha256.h \ curl_sspi.h \ curl_threads.h \ + curl_trc.h \ curlx.h \ dict.h \ doh.h \ diff --git a/lib/cf-h1-proxy.c b/lib/cf-h1-proxy.c index b1d8cb618b..621d55332b 100644 --- a/lib/cf-h1-proxy.c +++ b/lib/cf-h1-proxy.c @@ -41,7 +41,7 @@ #include "cfilters.h" #include "cf-h1-proxy.h" #include "connect.h" -#include "curl_log.h" +#include "curl_trc.h" #include "curlx.h" #include "vtls/vtls.h" #include "transfer.h" @@ -175,36 +175,36 @@ static void h1_tunnel_go_state(struct Curl_cfilter *cf, /* entering this one */ switch(new_state) { 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); break; 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->keepon = KEEPON_CONNECT; Curl_dyn_reset(&ts->rcvbuf); break; 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; break; 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; break; 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"); data->state.authproxy.done = TRUE; data->state.authproxy.multipass = FALSE; /* FALLTHROUGH */ case 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; Curl_dyn_reset(&ts->rcvbuf); Curl_dyn_reset(&ts->req); @@ -416,7 +416,7 @@ static CURLcode on_resp_header(struct Curl_cfilter *cf, if(!auth) 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); free(auth); @@ -638,7 +638,7 @@ static CURLcode recv_CONNECT_resp(struct Curl_cfilter *cf, /* without content-length or chunked encoding, we can't keep the connection alive since the close is 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; } } @@ -977,7 +977,7 @@ static CURLcode H1_CONNECT(struct Curl_cfilter *cf, switch(ts->tunnel_state) { case H1_TUNNEL_INIT: /* 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); if(result) goto out; @@ -986,7 +986,7 @@ static CURLcode H1_CONNECT(struct Curl_cfilter *cf, case H1_TUNNEL_CONNECT: /* 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); if(result || !done) goto out; @@ -995,7 +995,7 @@ static CURLcode H1_CONNECT(struct Curl_cfilter *cf, case H1_TUNNEL_RECEIVE: /* 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); if(Curl_pgrsUpdate(data)) { result = CURLE_ABORTED_BY_CALLBACK; @@ -1009,7 +1009,7 @@ static CURLcode H1_CONNECT(struct Curl_cfilter *cf, /* FALLTHROUGH */ case H1_TUNNEL_RESPONSE: - DEBUGF(LOG_CF(data, cf, "CONNECT response")); + CURL_TRC_CF(data, cf, "CONNECT response"); if(data->req.newurl) { /* not the "final" response, we need to do a follow up request. * 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 * 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"); Curl_conn_cf_close(cf, data); connkeep(conn, "HTTP proxy CONNECT"); @@ -1075,7 +1075,7 @@ static CURLcode cf_h1_proxy_connect(struct Curl_cfilter *cf, 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); if(result || !*done) 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, struct Curl_easy *data) { - DEBUGF(LOG_CF(data, cf, "destroy")); + CURL_TRC_CF(data, cf, "destroy"); tunnel_free(cf, data); } static void cf_h1_proxy_close(struct Curl_cfilter *cf, struct Curl_easy *data) { - DEBUGF(LOG_CF(data, cf, "close")); + CURL_TRC_CF(data, cf, "close"); cf->connected = FALSE; if(cf->ctx) { h1_tunnel_go_state(cf, cf->ctx, H1_TUNNEL_INIT, data); diff --git a/lib/cf-h2-proxy.c b/lib/cf-h2-proxy.c index 14cb1acb6c..b3d28e8bdf 100644 --- a/lib/cf-h2-proxy.c +++ b/lib/cf-h2-proxy.c @@ -30,7 +30,7 @@ #include "urldata.h" #include "cfilters.h" #include "connect.h" -#include "curl_log.h" +#include "curl_trc.h" #include "bufq.h" #include "dynbuf.h" #include "dynhds.h" @@ -146,29 +146,29 @@ static void h2_tunnel_go_state(struct Curl_cfilter *cf, /* entering this one */ switch(new_state) { 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); break; 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; break; 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; break; 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"); data->state.authproxy.done = TRUE; data->state.authproxy.multipass = FALSE; /* FALLTHROUGH */ case 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; /* 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 @@ -232,8 +232,8 @@ static void drain_tunnel(struct Curl_cfilter *cf, if(!tunnel->closed && !tunnel->reset && tunnel->upload_blocked_len) bits |= CURL_CSELECT_OUT; if(data->state.dselect_bits != bits) { - DEBUGF(LOG_CF(data, cf, "[h2sid=%d] DRAIN dselect_bits=%x", - tunnel->stream_id, bits)); + CURL_TRC_CF(data, cf, "[h2sid=%d] DRAIN dselect_bits=%x", + tunnel->stream_id, bits); data->state.dselect_bits = bits; Curl_expire(data, 0, EXPIRE_RUN_NOW); } @@ -248,8 +248,8 @@ static ssize_t proxy_nw_in_reader(void *reader_ctx, ssize_t nread; nread = Curl_conn_cf_recv(cf->next, data, (char *)buf, buflen, err); - DEBUGF(LOG_CF(data, cf, "nw_in_reader(len=%zu) -> %zd, %d", - buflen, nread, *err)); + CURL_TRC_CF(data, cf, "nw_in_reader(len=%zu) -> %zd, %d", + buflen, nread, *err); return nread; } @@ -262,8 +262,8 @@ static ssize_t proxy_h2_nw_out_writer(void *writer_ctx, ssize_t nwritten; 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", - buflen, nwritten, *err)); + CURL_TRC_CF(data, cf, "nw_out_writer(len=%zu) -> %zd, %d", + buflen, nwritten, *err); return nwritten; } @@ -384,7 +384,7 @@ static CURLcode cf_h2_proxy_ctx_init(struct Curl_cfilter *cf, out: if(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; } @@ -409,13 +409,13 @@ static CURLcode proxy_h2_nw_out_flush(struct Curl_cfilter *cf, &result); if(nwritten < 0) { if(result == CURLE_AGAIN) { - DEBUGF(LOG_CF(data, cf, "flush nw send buffer(%zu) -> EAGAIN", - Curl_bufq_len(&ctx->outbufq))); + CURL_TRC_CF(data, cf, "flush nw send buffer(%zu) -> EAGAIN", + Curl_bufq_len(&ctx->outbufq)); ctx->nw_out_blocked = 1; } 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; } @@ -436,8 +436,7 @@ static int proxy_h2_process_pending_input(struct Curl_cfilter *cf, while(Curl_bufq_peek(&ctx->inbufq, &buf, &blen)) { rv = nghttp2_session_mem_recv(ctx->h2, (const uint8_t *)buf, blen); - DEBUGF(LOG_CF(data, cf, - "fed %zu bytes from nw to nghttp2 -> %zd", blen, rv)); + CURL_TRC_CF(data, cf, "fed %zu bytes from nw to nghttp2 -> %zd", blen, rv); if(rv < 0) { failf(data, "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); 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; } else { - DEBUGF(LOG_CF(data, cf, "process_pending_input: %zu bytes left " - "in connection buffer", Curl_bufq_len(&ctx->inbufq))); + CURL_TRC_CF(data, cf, "process_pending_input: %zu bytes left " + "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 */ if(!Curl_bufq_is_empty(&ctx->inbufq)) { - DEBUGF(LOG_CF(data, cf, "Process %zu bytes in connection buffer", - Curl_bufq_len(&ctx->inbufq))); + CURL_TRC_CF(data, cf, "Process %zu bytes in connection buffer", + Curl_bufq_len(&ctx->inbufq)); if(proxy_h2_process_pending_input(cf, data, &result) < 0) return result; } @@ -482,8 +481,8 @@ static CURLcode proxy_h2_progress_ingress(struct Curl_cfilter *cf, !Curl_bufq_is_full(&ctx->tunnel.recvbuf)) { nread = Curl_bufq_slurp(&ctx->inbufq, proxy_nw_in_reader, cf, &result); - DEBUGF(LOG_CF(data, cf, "read %zu bytes nw data -> %zd, %d", - Curl_bufq_len(&ctx->inbufq), nread, result)); + CURL_TRC_CF(data, cf, "read %zu bytes nw data -> %zd, %d", + Curl_bufq_len(&ctx->inbufq), nread, result); if(nread < 0) { if(result != CURLE_AGAIN) { 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); if(nghttp2_is_fatal(rv)) { - DEBUGF(LOG_CF(data, cf, "nghttp2_session_send error (%s)%d", - nghttp2_strerror(rv), rv)); + CURL_TRC_CF(data, cf, "nghttp2_session_send error (%s)%d", + nghttp2_strerror(rv), rv); return CURLE_SEND_ERROR; } 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; break; case NGHTTP2_WINDOW_UPDATE: - DEBUGF(LOG_CF(data, cf, "recv frame WINDOW_UPDATE")); + CURL_TRC_CF(data, cf, "recv frame WINDOW_UPDATE"); break; 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; } if(stream_id != ctx->tunnel.stream_id) { - DEBUGF(LOG_CF(data, cf, "[h2sid=%u] rcvd FRAME not for tunnel", - stream_id)); + CURL_TRC_CF(data, cf, "[h2sid=%u] rcvd FRAME not for tunnel", stream_id); return NGHTTP2_ERR_CALLBACK_FAILURE; } switch(frame->hd.type) { case NGHTTP2_DATA: /* If body started on this stream, then receiving DATA is illegal. */ - 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; 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 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) return NGHTTP2_ERR_CALLBACK_FAILURE; /* Only final status code signals the end of header */ - DEBUGF(LOG_CF(data, cf, "[h2sid=%u] got http status: %d", - stream_id, ctx->tunnel.resp->status)); + CURL_TRC_CF(data, cf, "[h2sid=%u] got http status: %d", + stream_id, ctx->tunnel.resp->status); if(!ctx->tunnel.has_final_response) { if(ctx->tunnel.resp->status / 100 != 1) { ctx->tunnel.has_final_response = TRUE; @@ -616,25 +614,25 @@ static int proxy_h2_on_frame_recv(nghttp2_session *session, } break; 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; 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; break; 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) && (data->req.keepon & KEEP_SEND)) { data->req.keepon &= ~KEEP_SEND_HOLD; Curl_expire(data, 0, EXPIRE_RUN_NOW); - DEBUGF(LOG_CF(data, cf, "[h2sid=%u] unpausing after win update", - stream_id)); + CURL_TRC_CF(data, cf, "[h2sid=%u] unpausing after win update", + stream_id); } break; default: - DEBUGF(LOG_CF(data, cf, "[h2sid=%u] recv frame %x", - stream_id, frame->hd.type)); + CURL_TRC_CF(data, cf, "[h2sid=%u] recv frame %x", + stream_id, frame->hd.type); break; } return 0; @@ -658,10 +656,9 @@ static int proxy_h2_on_header(nghttp2_session *session, (void)session; DEBUGASSERT(stream_id); /* should never be a zero stream ID here */ if(stream_id != ctx->tunnel.stream_id) { - DEBUGF(LOG_CF(data, cf, "[h2sid=%u] header for non-tunnel stream: " - "%.*s: %.*s", stream_id, - (int)namelen, name, - (int)valuelen, value)); + CURL_TRC_CF(data, cf, "[h2sid=%u] header for non-tunnel stream: " + "%.*s: %.*s", stream_id, + (int)namelen, name, (int)valuelen, value); return NGHTTP2_ERR_CALLBACK_FAILURE; } @@ -689,8 +686,8 @@ static int proxy_h2_on_header(nghttp2_session *session, return NGHTTP2_ERR_CALLBACK_FAILURE; resp->prev = ctx->tunnel.resp; ctx->tunnel.resp = resp; - DEBUGF(LOG_CF(data, cf, "[h2sid=%u] status: HTTP/2 %03d", - stream_id, ctx->tunnel.resp->status)); + CURL_TRC_CF(data, cf, "[h2sid=%u] status: HTTP/2 %03d", + stream_id, ctx->tunnel.resp->status); return 0; } @@ -703,10 +700,8 @@ static int proxy_h2_on_header(nghttp2_session *session, if(result) return NGHTTP2_ERR_CALLBACK_FAILURE; - DEBUGF(LOG_CF(data, cf, "[h2sid=%u] header: %.*s: %.*s", - stream_id, - (int)namelen, name, - (int)valuelen, value)); + CURL_TRC_CF(data, cf, "[h2sid=%u] header: %.*s: %.*s", + stream_id, (int)namelen, name, (int)valuelen, value); 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)) *data_flags = NGHTTP2_DATA_FLAG_EOF; - DEBUGF(LOG_CF(data, cf, "[h2sid=%u] tunnel_send_callback -> %zd", - ts->stream_id, nread)); + CURL_TRC_CF(data, cf, "[h2sid=%u] tunnel_send_callback -> %zd", + ts->stream_id, nread); return nread; } @@ -791,8 +786,8 @@ static int proxy_h2_on_stream_close(nghttp2_session *session, if(stream_id != ctx->tunnel.stream_id) return 0; - DEBUGF(LOG_CF(data, cf, "[h2sid=%u] proxy_h2_on_stream_close, %s (err %d)", - stream_id, nghttp2_http2_strerror(error_code), error_code)); + CURL_TRC_CF(data, cf, "[h2sid=%u] proxy_h2_on_stream_close, %s (err %d)", + stream_id, nghttp2_http2_strerror(error_code), error_code); ctx->tunnel.closed = TRUE; ctx->tunnel.error = error_code; @@ -910,8 +905,8 @@ static CURLcode submit_CONNECT(struct Curl_cfilter *cf, result = proxy_h2_submit(&ts->stream_id, cf, data, ctx->h2, req, NULL, ts, tunnel_send_callback, cf); if(result) { - DEBUGF(LOG_CF(data, cf, "send: nghttp2_submit_request error (%s)%u", - nghttp2_strerror(ts->stream_id), ts->stream_id)); + CURL_TRC_CF(data, cf, "send: nghttp2_submit_request error (%s)%u", + nghttp2_strerror(ts->stream_id), ts->stream_id); } out: @@ -945,8 +940,8 @@ static CURLcode inspect_response(struct Curl_cfilter *cf, } if(auth_reply) { - DEBUGF(LOG_CF(data, cf, "CONNECT: fwd auth header '%s'", - auth_reply->value)); + CURL_TRC_CF(data, cf, "CONNECT: fwd auth header '%s'", + auth_reply->value); result = Curl_http_input_auth(data, ts->resp->status == 407, auth_reply->value); if(result) @@ -976,7 +971,7 @@ static CURLcode H2_CONNECT(struct Curl_cfilter *cf, switch(ts->state) { case H2_TUNNEL_INIT: /* Prepare the CONNECT request and make a first attempt to send. */ - 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); if(result) goto out; @@ -1143,8 +1138,8 @@ static ssize_t h2_handle_tunnel_close(struct Curl_cfilter *cf, ssize_t rv = 0; if(ctx->tunnel.error == NGHTTP2_REFUSED_STREAM) { - DEBUGF(LOG_CF(data, cf, "[h2sid=%u] REFUSED_STREAM, try again on a new " - "connection", ctx->tunnel.stream_id)); + CURL_TRC_CF(data, cf, "[h2sid=%u] REFUSED_STREAM, try again on a new " + "connection", ctx->tunnel.stream_id); connclose(cf->conn, "REFUSED_STREAM"); /* don't use this anymore */ *err = CURLE_RECV_ERROR; /* trigger Curl_retry_request() later */ return -1; @@ -1164,7 +1159,7 @@ static ssize_t h2_handle_tunnel_close(struct Curl_cfilter *cf, *err = CURLE_OK; 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; } @@ -1200,8 +1195,8 @@ static ssize_t tunnel_recv(struct Curl_cfilter *cf, struct Curl_easy *data, } out: - DEBUGF(LOG_CF(data, cf, "tunnel_recv(len=%zu) -> %zd, %d", - len, nread, *err)); + CURL_TRC_CF(data, cf, "tunnel_recv(len=%zu) -> %zd, %d", + len, nread, *err); 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); if(nread > 0) { - DEBUGF(LOG_CF(data, cf, "[h2sid=%u] increase window by %zd", - ctx->tunnel.stream_id, nread)); + CURL_TRC_CF(data, cf, "[h2sid=%u] increase window by %zd", + ctx->tunnel.stream_id, 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. */ drain_tunnel(cf, data, &ctx->tunnel); } - DEBUGF(LOG_CF(data, cf, "[h2sid=%u] cf_recv(len=%zu) -> %zd %d", - ctx->tunnel.stream_id, len, nread, *err)); + CURL_TRC_CF(data, cf, "[h2sid=%u] cf_recv(len=%zu) -> %zd %d", + ctx->tunnel.stream_id, len, nread, *err); CF_DATA_RESTORE(cf, save); 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 * window increases. * We *could* iterate over all data on this conn maybe? */ - DEBUGF(LOG_CF(data, cf, "[h2sid=%d] remote flow " - "window is exhausted", ctx->tunnel.stream_id)); + CURL_TRC_CF(data, cf, "[h2sid=%d] remote flow " + "window is exhausted", ctx->tunnel.stream_id); } /* Whatever the cause, we need to return CURL_EAGAIN for this call. * We have unwritten state that needs us being invoked again and EAGAIN * is the only way to ensure that. */ ctx->tunnel.upload_blocked_len = nwritten; - DEBUGF(LOG_CF(data, cf, "[h2sid=%d] cf_send(len=%zu) BLOCK: win %u/%zu " - "blocked_len=%zu", - ctx->tunnel.stream_id, len, - nghttp2_session_get_remote_window_size(ctx->h2), rwin, - nwritten)); + CURL_TRC_CF(data, cf, "[h2sid=%d] cf_send(len=%zu) BLOCK: win %u/%zu " + "blocked_len=%zu", + ctx->tunnel.stream_id, len, + nghttp2_session_get_remote_window_size(ctx->h2), rwin, + nwritten); *err = CURLE_AGAIN; nwritten = -1; goto out; @@ -1371,22 +1366,21 @@ static ssize_t cf_h2_proxy_send(struct Curl_cfilter *cf, nwritten = -1; } 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; nwritten = -1; } } out: - DEBUGF(LOG_CF(data, cf, "[h2sid=%d] cf_send(len=%zu) -> %zd, %d, " - "h2 windows %d-%d (stream-conn), " - "buffers %zu-%zu (stream-conn)", - ctx->tunnel.stream_id, len, nwritten, *err, - nghttp2_session_get_stream_remote_window_size( + CURL_TRC_CF(data, cf, "[h2sid=%d] cf_send(len=%zu) -> %zd, %d, " + "h2 windows %d-%d (stream-conn), buffers %zu-%zu (stream-conn)", + ctx->tunnel.stream_id, len, nwritten, *err, + nghttp2_session_get_stream_remote_window_size( ctx->h2, ctx->tunnel.stream_id), - nghttp2_session_get_remote_window_size(ctx->h2), - Curl_bufq_len(&ctx->tunnel.sendbuf), - Curl_bufq_len(&ctx->outbufq))); + nghttp2_session_get_remote_window_size(ctx->h2), + Curl_bufq_len(&ctx->tunnel.sendbuf), + Curl_bufq_len(&ctx->outbufq)); CF_DATA_RESTORE(cf, save); return nwritten; } @@ -1438,8 +1432,8 @@ static bool cf_h2_proxy_is_alive(struct Curl_cfilter *cf, CF_DATA_SAVE(save, cf, data); result = (ctx && ctx->h2 && proxy_h2_connisalive(cf, data, input_pending)); - DEBUGF(LOG_CF(data, cf, "conn alive -> %d, input_pending=%d", - result, *input_pending)); + CURL_TRC_CF(data, cf, "conn alive -> %d, input_pending=%d", + result, *input_pending); CF_DATA_RESTORE(cf, save); return result; } @@ -1447,7 +1441,7 @@ static bool cf_h2_proxy_is_alive(struct Curl_cfilter *cf, struct Curl_cftype Curl_cft_h2_proxy = { "H2-PROXY", CF_TYPE_IP_CONNECT, - CURL_LOG_DEFAULT, + CURL_LOG_LVL_NONE, cf_h2_proxy_destroy, cf_h2_proxy_connect, cf_h2_proxy_close, diff --git a/lib/cf-haproxy.c b/lib/cf-haproxy.c index ec0100ca9e..5c8e8e620c 100644 --- a/lib/cf-haproxy.c +++ b/lib/cf-haproxy.c @@ -30,7 +30,7 @@ #include "urldata.h" #include "cfilters.h" #include "cf-haproxy.h" -#include "curl_log.h" +#include "curl_trc.h" #include "multiif.h" /* 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) { (void)data; - DEBUGF(LOG_CF(data, cf, "destroy")); + CURL_TRC_CF(data, cf, "destroy"); cf_haproxy_ctx_free(cf->ctx); } static void cf_haproxy_close(struct Curl_cfilter *cf, struct Curl_easy *data) { - DEBUGF(LOG_CF(data, cf, "close")); + CURL_TRC_CF(data, cf, "close"); cf->connected = FALSE; cf_haproxy_ctx_reset(cf->ctx); if(cf->next) diff --git a/lib/cf-https-connect.c b/lib/cf-https-connect.c index 4e4d4b117d..be54aec740 100644 --- a/lib/cf-https-connect.c +++ b/lib/cf-https-connect.c @@ -28,7 +28,7 @@ #include "urldata.h" #include -#include "curl_log.h" +#include "curl_trc.h" #include "cfilters.h" #include "connect.h" #include "multiif.h" @@ -165,9 +165,9 @@ static CURLcode baller_connected(struct Curl_cfilter *cf, if(winner != &ctx->h21_baller) cf_hc_baller_reset(&ctx->h21_baller, data); - DEBUGF(LOG_CF(data, cf, "connect+handshake %s: %dms, 1st data: %dms", - winner->name, (int)Curl_timediff(Curl_now(), winner->started), - cf_hc_baller_reply_ms(winner, data))); + CURL_TRC_CF(data, cf, "connect+handshake %s: %dms, 1st data: %dms", + winner->name, (int)Curl_timediff(Curl_now(), winner->started), + cf_hc_baller_reply_ms(winner, data)); cf->next = winner->cf; winner->cf = NULL; @@ -218,16 +218,16 @@ static bool time_to_start_h21(struct Curl_cfilter *cf, elapsed_ms = Curl_timediff(now, ctx->started); if(elapsed_ms >= ctx->hard_eyeballs_timeout_ms) { - DEBUGF(LOG_CF(data, cf, "hard timeout of %dms reached, starting h21", - ctx->hard_eyeballs_timeout_ms)); + CURL_TRC_CF(data, cf, "hard timeout of %dms reached, starting h21", + ctx->hard_eyeballs_timeout_ms); return TRUE; } if(elapsed_ms >= ctx->soft_eyeballs_timeout_ms) { if(cf_hc_baller_reply_ms(&ctx->h3_baller, data) < 0) { - DEBUGF(LOG_CF(data, cf, "soft timeout of %dms reached, h3 has not " - "seen any data, starting h21", - ctx->soft_eyeballs_timeout_ms)); + CURL_TRC_CF(data, cf, "soft timeout of %dms reached, h3 has not " + "seen any data, starting h21", + ctx->soft_eyeballs_timeout_ms); return TRUE; } /* 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->h21_baller.cf); DEBUGASSERT(!cf->next); - DEBUGF(LOG_CF(data, cf, "connect, init")); + CURL_TRC_CF(data, cf, "connect, init"); ctx->started = now; if(ctx->h3_baller.enabled) { 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)) { - 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); if(!result && *done) { 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) && (!ctx->h21_baller.enabled || ctx->h21_baller.result)) { /* 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? ctx->h3_baller.result : ctx->h21_baller.result; ctx->state = CF_HC_FAILURE; @@ -321,7 +321,7 @@ static CURLcode cf_hc_connect(struct Curl_cfilter *cf, } 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; } @@ -345,7 +345,7 @@ static int cf_hc_get_select_socks(struct Curl_cfilter *cf, if(!cf_hc_baller_is_active(b)) continue; 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) continue; 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; } @@ -371,7 +371,7 @@ static bool cf_hc_data_pending(struct Curl_cfilter *cf, if(cf->connected) 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) || 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) { - DEBUGF(LOG_CF(data, cf, "close")); + CURL_TRC_CF(data, cf, "close"); cf_hc_reset(cf, data); 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; (void)data; - DEBUGF(LOG_CF(data, cf, "destroy")); + CURL_TRC_CF(data, cf, "destroy"); cf_hc_reset(cf, data); 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 = { "HTTPS-CONNECT", 0, - CURL_LOG_DEFAULT, + CURL_LOG_LVL_NONE, cf_hc_destroy, cf_hc_connect, cf_hc_close, diff --git a/lib/cf-socket.c b/lib/cf-socket.c index 5729fe07fa..e209eea1be 100644 --- a/lib/cf-socket.c +++ b/lib/cf-socket.c @@ -632,7 +632,7 @@ static CURLcode bindlocal(struct Curl_easy *data, struct connectdata *conn, port++; /* try next port */ if(port == 0) 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 */ if(sock->sa_family == AF_INET) si4->sin_port = ntohs(port); @@ -836,8 +836,8 @@ static ssize_t nw_in_read(void *reader_ctx, nread = -1; } } - DEBUGF(LOG_CF(rctx->data, rctx->cf, "nw_in_read(len=%zu) -> %d, err=%d", - len, (int)nread, *err)); + CURL_TRC_CF(rctx->data, rctx->cf, "nw_in_read(len=%zu) -> %d, err=%d", + len, (int)nread, *err); 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. */ if(ctx->sock == cf->conn->sock[cf->sockindex]) { - DEBUGF(LOG_CF(data, cf, "cf_socket_close(%" CURL_FORMAT_SOCKET_T - ", active)", ctx->sock)); + CURL_TRC_CF(data, cf, "cf_socket_close(%" CURL_FORMAT_SOCKET_T + ", active)", ctx->sock); socket_close(data, cf->conn, !ctx->accepted, ctx->sock); cf->conn->sock[cf->sockindex] = CURL_SOCKET_BAD; } else { - DEBUGF(LOG_CF(data, cf, "cf_socket_close(%" CURL_FORMAT_SOCKET_T - ") no longer at conn->sock[], discarding", ctx->sock)); + CURL_TRC_CF(data, cf, "cf_socket_close(%" CURL_FORMAT_SOCKET_T + ") no longer at conn->sock[], discarding", ctx->sock); /* TODO: we do not want this to happen. Need to check which * 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 { /* this is our local socket, we did never publish it */ - DEBUGF(LOG_CF(data, cf, "cf_socket_close(%" CURL_FORMAT_SOCKET_T - ", not active)", ctx->sock)); + CURL_TRC_CF(data, cf, "cf_socket_close(%" CURL_FORMAT_SOCKET_T + ", not active)", ctx->sock); socket_close(data, cf->conn, !ctx->accepted, ctx->sock); 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; cf_socket_close(cf, data); - DEBUGF(LOG_CF(data, cf, "destroy")); + CURL_TRC_CF(data, cf, "destroy"); Curl_bufq_free(&ctx->recvbuf); free(ctx); cf->ctx = NULL; @@ -1047,8 +1047,8 @@ out: ctx->connected_at = Curl_now(); cf->connected = TRUE; } - DEBUGF(LOG_CF(data, cf, "cf_socket_open() -> %d, fd=%" CURL_FORMAT_SOCKET_T, - result, ctx->sock)); + CURL_TRC_CF(data, cf, "cf_socket_open() -> %d, fd=%" CURL_FORMAT_SOCKET_T, + result, ctx->sock); return result; } @@ -1155,7 +1155,7 @@ static CURLcode cf_tcp_connect(struct Curl_cfilter *cf, rc = SOCKET_WRITABLE(ctx->sock, 0); 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; } 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); *done = TRUE; cf->connected = TRUE; - DEBUGF(LOG_CF(data, cf, "connected")); + CURL_TRC_CF(data, cf, "connected"); 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", - len, (int)nwritten, *err)); + CURL_TRC_CF(data, cf, "send(len=%zu) -> %d, err=%d", + len, (int)nwritten, *err); cf->conn->sock[cf->sockindex] = fdsave; 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; 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); } 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)) { /* we have a partial read with an error. need to deliver * 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); } else if(nwritten < 0) { @@ -1337,7 +1337,7 @@ static ssize_t cf_socket_recv(struct Curl_cfilter *cf, struct Curl_easy *data, nread = 0; } 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); } } @@ -1347,8 +1347,8 @@ static ssize_t cf_socket_recv(struct Curl_cfilter *cf, struct Curl_easy *data, } out: - DEBUGF(LOG_CF(data, cf, "recv(len=%zu) -> %d, err=%d", len, (int)nread, - *err)); + CURL_TRC_CF(data, cf, "recv(len=%zu) -> %d, err=%d", len, (int)nread, + *err); if(nread > 0 && !ctx->got_first_byte) { ctx->first_byte_at = Curl_now(); 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); 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; } 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; } 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; } - 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; return TRUE; } @@ -1520,7 +1520,7 @@ static CURLcode cf_socket_query(struct Curl_cfilter *cf, struct Curl_cftype Curl_cft_tcp = { "TCP", CF_TYPE_IP_CONNECT, - CURL_LOG_DEFAULT, + CURL_LOG_LVL_NONE, cf_socket_destroy, cf_tcp_connect, 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); } set_local_ip(cf, data); - DEBUGF(LOG_CF(data, cf, "%s socket %" CURL_FORMAT_SOCKET_T - " connected: [%s:%d] -> [%s:%d]", - (ctx->transport == TRNSPRT_QUIC)? "QUIC" : "UDP", - ctx->sock, ctx->l_ip, ctx->l_port, ctx->r_ip, ctx->r_port)); + CURL_TRC_CF(data, cf, "%s socket %" CURL_FORMAT_SOCKET_T + " connected: [%s:%d] -> [%s:%d]", + (ctx->transport == TRNSPRT_QUIC)? "QUIC" : "UDP", + ctx->sock, ctx->l_ip, ctx->l_port, ctx->r_ip, ctx->r_port); (void)curlx_nonblock(ctx->sock, TRUE); switch(ctx->addr.family) { @@ -1624,7 +1624,7 @@ static CURLcode cf_udp_connect(struct Curl_cfilter *cf, if(ctx->sock == CURL_SOCKET_BAD) { result = cf_socket_open(cf, data); 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; } @@ -1632,13 +1632,13 @@ static CURLcode cf_udp_connect(struct Curl_cfilter *cf, result = cf_udp_setup_quic(cf, data); if(result) goto out; - DEBUGF(LOG_CF(data, cf, "cf_udp_connect(), opened socket=%" - CURL_FORMAT_SOCKET_T " (%s:%d)", - ctx->sock, ctx->l_ip, ctx->l_port)); + CURL_TRC_CF(data, cf, "cf_udp_connect(), opened socket=%" + CURL_FORMAT_SOCKET_T " (%s:%d)", + ctx->sock, ctx->l_ip, ctx->l_port); } else { - DEBUGF(LOG_CF(data, cf, "cf_udp_connect(), opened socket=%" - CURL_FORMAT_SOCKET_T " (unconnected)", ctx->sock)); + CURL_TRC_CF(data, cf, "cf_udp_connect(), opened socket=%" + CURL_FORMAT_SOCKET_T " (unconnected)", ctx->sock); } *done = TRUE; cf->connected = TRUE; @@ -1650,7 +1650,7 @@ out: struct Curl_cftype Curl_cft_udp = { "UDP", CF_TYPE_IP_CONNECT, - CURL_LOG_DEFAULT, + CURL_LOG_LVL_NONE, cf_socket_destroy, cf_udp_connect, cf_socket_close, @@ -1701,7 +1701,7 @@ out: struct Curl_cftype Curl_cft_unix = { "UNIX", CF_TYPE_IP_CONNECT, - CURL_LOG_DEFAULT, + CURL_LOG_LVL_NONE, cf_socket_destroy, cf_tcp_connect, cf_socket_close, @@ -1765,7 +1765,7 @@ static CURLcode cf_tcp_accept_connect(struct Curl_cfilter *cf, struct Curl_cftype Curl_cft_tcp_accept = { "TCP-ACCEPT", CF_TYPE_IP_CONNECT, - CURL_LOG_DEFAULT, + CURL_LOG_LVL_NONE, cf_socket_destroy, cf_tcp_accept_connect, cf_socket_close, @@ -1810,8 +1810,8 @@ CURLcode Curl_conn_tcp_listen_set(struct Curl_easy *data, ctx->active = TRUE; ctx->connected_at = Curl_now(); cf->connected = TRUE; - DEBUGF(LOG_CF(data, cf, "Curl_conn_tcp_listen_set(%" - CURL_FORMAT_SOCKET_T ")", ctx->sock)); + CURL_TRC_CF(data, cf, "Curl_conn_tcp_listen_set(%" + CURL_FORMAT_SOCKET_T ")", ctx->sock); out: if(result) { @@ -1875,9 +1875,9 @@ CURLcode Curl_conn_tcp_accepted_set(struct Curl_easy *data, ctx->accepted = TRUE; ctx->connected_at = Curl_now(); cf->connected = TRUE; - DEBUGF(LOG_CF(data, cf, "accepted_set(sock=%" CURL_FORMAT_SOCKET_T - ", remote=%s port=%d)", - ctx->sock, ctx->r_ip, ctx->r_port)); + CURL_TRC_CF(data, cf, "accepted_set(sock=%" CURL_FORMAT_SOCKET_T + ", remote=%s port=%d)", + ctx->sock, ctx->r_ip, ctx->r_port); return CURLE_OK; } diff --git a/lib/cfilters.c b/lib/cfilters.c index 216d0b4f68..016f35b643 100644 --- a/lib/cfilters.c +++ b/lib/cfilters.c @@ -238,7 +238,7 @@ void Curl_conn_cf_add(struct Curl_easy *data, cf->conn = conn; cf->sockindex = index; 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, diff --git a/lib/connect.c b/lib/connect.c index dc93533f6c..98a733ee7f 100644 --- a/lib/connect.c +++ b/lib/connect.c @@ -475,7 +475,7 @@ static void baller_initiate(struct Curl_cfilter *cf, out: if(result) { - DEBUGF(LOG_CF(data, cf, "%s failed", baller->name)); + CURL_TRC_CF(data, cf, "%s failed", baller->name); baller_close(baller, data); } if(cf_prev) @@ -601,8 +601,8 @@ evaluate: continue; } baller->result = baller_connect(cf, data, baller, &now, connected); - DEBUGF(LOG_CF(data, cf, "%s connect -> %d, connected=%d", - baller->name, baller->result, *connected)); + CURL_TRC_CF(data, cf, "%s connect -> %d, connected=%d", + baller->name, baller->result, *connected); if(!baller->result) { if(*connected) { @@ -623,11 +623,11 @@ evaluate: } baller_start_next(cf, data, baller, Curl_timeleft(data, &now, TRUE)); if(baller->is_done) { - DEBUGF(LOG_CF(data, cf, "%s done", baller->name)); + CURL_TRC_CF(data, cf, "%s done", baller->name); } else { /* 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; } } @@ -661,12 +661,12 @@ evaluate: Curl_timediff(now, ctx->started) >= baller->delay_ms) { baller_start(cf, data, baller, Curl_timeleft(data, &now, TRUE)); if(baller->is_done) { - DEBUGF(LOG_CF(data, cf, "%s done", baller->name)); + CURL_TRC_CF(data, cf, "%s done", baller->name); } else { - DEBUGF(LOG_CF(data, cf, "%s starting (timeout=%" - CURL_FORMAT_TIMEDIFF_T "ms)", - baller->name, baller->timeoutms)); + CURL_TRC_CF(data, cf, "%s starting (timeout=%" + CURL_FORMAT_TIMEDIFF_T "ms)", + baller->name, baller->timeoutms); ++ongoing; ++added; } @@ -683,14 +683,14 @@ evaluate: } /* 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; for(i = 0; i < sizeof(ctx->baller)/sizeof(ctx->baller[0]); i++) { struct eyeballer *baller = ctx->baller[i]; - DEBUGF(LOG_CF(data, cf, "%s assess started=%d, result=%d", - baller?baller->name:NULL, - baller?baller->has_started:0, - baller?baller->result:0)); + CURL_TRC_CF(data, cf, "%s assess started=%d, result=%d", + baller?baller->name:NULL, + baller?baller->has_started:0, + baller?baller->result:0); if(baller && baller->has_started && baller->result) { result = baller->result; break; @@ -803,9 +803,9 @@ static CURLcode start_connect(struct Curl_cfilter *cf, timeout_ms, EXPIRE_DNS_PER_NAME); if(result) return result; - DEBUGF(LOG_CF(data, cf, "created %s (timeout %" - CURL_FORMAT_TIMEDIFF_T "ms)", - ctx->baller[0]->name, ctx->baller[0]->timeoutms)); + CURL_TRC_CF(data, cf, "created %s (timeout %" + CURL_FORMAT_TIMEDIFF_T "ms)", + ctx->baller[0]->name, ctx->baller[0]->timeoutms); if(addr1) { /* second one gets a delayed start */ 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); if(result) return result; - DEBUGF(LOG_CF(data, cf, "created %s (timeout %" - CURL_FORMAT_TIMEDIFF_T "ms)", - ctx->baller[1]->name, ctx->baller[1]->timeoutms)); + CURL_TRC_CF(data, cf, "created %s (timeout %" + CURL_FORMAT_TIMEDIFF_T "ms)", + ctx->baller[1]->name, ctx->baller[1]->timeoutms); } 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; - DEBUGF(LOG_CF(data, cf, "close")); + CURL_TRC_CF(data, cf, "close"); cf_he_ctx_clear(cf, data); cf->connected = FALSE; ctx->state = SCFST_INIT; @@ -1007,7 +1007,7 @@ static CURLcode cf_he_query(struct Curl_cfilter *cf, } } *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; } 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; - DEBUGF(LOG_CF(data, cf, "destroy")); + CURL_TRC_CF(data, cf, "destroy"); if(ctx) { 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 = { "HAPPY-EYEBALLS", 0, - CURL_LOG_DEFAULT, + CURL_LOG_LVL_NONE, cf_he_destroy, cf_he_connect, cf_he_close, @@ -1148,7 +1148,7 @@ static CURLcode cf_he_insert_after(struct Curl_cfilter *cf_at, DEBUGASSERT(cf_at); cf_create = get_cf_create(transport); 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; } 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; - DEBUGF(LOG_CF(data, cf, "close")); + CURL_TRC_CF(data, cf, "close"); cf->connected = FALSE; 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; (void)data; - DEBUGF(LOG_CF(data, cf, "destroy")); + CURL_TRC_CF(data, cf, "destroy"); 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 = { "SETUP", 0, - CURL_LOG_DEFAULT, + CURL_LOG_LVL_NONE, cf_setup_destroy, cf_setup_connect, cf_setup_close, diff --git a/lib/curl_log.h b/lib/curl_log.h deleted file mode 100644 index ebfa5a0003..0000000000 --- a/lib/curl_log.h +++ /dev/null @@ -1,121 +0,0 @@ -#ifndef HEADER_CURL_LOG_H -#define HEADER_CURL_LOG_H -/*************************************************************************** - * _ _ ____ _ - * Project ___| | | | _ \| | - * / __| | | | |_) | | - * | (__| |_| | _ <| |___ - * \___|\___/|_| \_\_____| - * - * Copyright (C) Daniel Stenberg, , 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 */ diff --git a/lib/curl_log.c b/lib/curl_trc.c similarity index 78% rename from lib/curl_log.c rename to lib/curl_trc.c index 782c35a632..76c35ba386 100644 --- a/lib/curl_log.c +++ b/lib/curl_trc.c @@ -26,7 +26,7 @@ #include -#include "curl_log.h" +#include "curl_trc.h" #include "urldata.h" #include "easyif.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, ...) { DEBUGASSERT(cf); - if(data && Curl_log_cf_is_debug(cf, data)) { + if(data && Curl_trc_cf_is_verbose(cf, data)) { va_list ap; int len; char buffer[MAXINFO + 2]; @@ -179,44 +179,67 @@ static struct Curl_cftype *cf_types[] = { NULL, }; -#ifndef ARRAYSIZE -#define ARRAYSIZE(A) (sizeof(A)/sizeof((A)[0])) -#endif - -CURLcode Curl_log_init(void) +CURLcode Curl_trc_opt(const char *config) { - const char *setting = getenv("CURL_DEBUG"); - if(setting) { - char *token, *tok_buf, *tmp; - size_t i; - - tmp = strdup(setting); - if(!tmp) - return CURLE_OUT_OF_MEMORY; - - token = strtok_r(tmp, ", ", &tok_buf); - while(token) { - for(i = 0; cf_types[i]; ++i) { - if(strcasecompare(token, cf_types[i]->name)) { - cf_types[i]->log_level = CURL_LOG_DEBUG; - break; - } + char *token, *tok_buf, *tmp; + size_t i; + int lvl; + + tmp = strdup(config); + if(!tmp) + return CURLE_OUT_OF_MEMORY; + + token = strtok_r(tmp, ", ", &tok_buf); + 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) { + if(strcasecompare(token, "all")) { + cf_types[i]->log_level = lvl; + } + else if(strcasecompare(token, cf_types[i]->name)) { + cf_types[i]->log_level = lvl; + break; } - token = strtok_r(NULL, ", ", &tok_buf); } - free(tmp); + token = strtok_r(NULL, ", ", &tok_buf); + } + free(tmp); + return CURLE_OK; +} + +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 /* DEBUGBUILD */ +#else /* !CURL_DISABLE_VERBOSE_STRINGS) */ -CURLcode Curl_log_init(void) +CURLcode Curl_trc_init(void) { return CURLE_OK; } #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, ...) { (void)data; diff --git a/lib/curl_trc.h b/lib/curl_trc.h new file mode 100644 index 0000000000..b9ac4f1279 --- /dev/null +++ b/lib/curl_trc.h @@ -0,0 +1,150 @@ +#ifndef HEADER_CURL_TRC_H +#define HEADER_CURL_TRC_H +/*************************************************************************** + * _ _ ____ _ + * Project ___| | | | _ \| | + * / __| | | | |_) | | + * | (__| |_| | _ <| |___ + * \___|\___/|_| \_\_____| + * + * Copyright (C) Daniel Stenberg, , 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 */ diff --git a/lib/easy.c b/lib/easy.c index 42cdbe0a77..8d23d9a305 100644 --- a/lib/easy.c +++ b/lib/easy.c @@ -158,8 +158,8 @@ static CURLcode global_init(long flags, bool memoryfuncs) #endif } - if(Curl_log_init()) { - DEBUGF(fprintf(stderr, "Error: Curl_log_init failed\n")); + if(Curl_trc_init()) { + DEBUGF(fprintf(stderr, "Error: Curl_trc_init failed\n")); goto fail; } @@ -315,6 +315,21 @@ void curl_global_cleanup(void) 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. */ diff --git a/lib/http2.c b/lib/http2.c index 6e1607cb77..25e965e6f9 100644 --- a/lib/http2.c +++ b/lib/http2.c @@ -217,8 +217,8 @@ static void drain_stream(struct Curl_cfilter *cf, (stream->upload_left || stream->upload_blocked_len)) bits |= CURL_CSELECT_OUT; if(data->state.dselect_bits != bits) { - DEBUGF(LOG_CF(data, cf, "[h2sid=%d] DRAIN dselect_bits=%x", - stream->id, bits)); + CURL_TRC_CF(data, cf, "[h2sid=%d] DRAIN dselect_bits=%x", + stream->id, bits); data->state.dselect_bits = bits; Curl_expire(data, 0, EXPIRE_RUN_NOW); } @@ -281,8 +281,8 @@ static void http2_data_done(struct Curl_cfilter *cf, if(ctx->h2) { if(!stream->closed && stream->id > 0) { /* RST_STREAM */ - DEBUGF(LOG_CF(data, cf, "[h2sid=%d] premature DATA_DONE, RST stream", - stream->id)); + CURL_TRC_CF(data, cf, "[h2sid=%d] premature DATA_DONE, RST stream", + stream->id); if(!nghttp2_submit_rst_stream(ctx->h2, NGHTTP2_FLAG_NONE, stream->id, NGHTTP2_STREAM_CLOSED)) (void)nghttp2_session_send(ctx->h2); @@ -535,8 +535,8 @@ static int h2_process_pending_input(struct Curl_cfilter *cf, break; } else { - DEBUGF(LOG_CF(data, cf, "process_pending_input: %zu bytes left " - "in connection buffer", Curl_bufq_len(&ctx->inbufq))); + CURL_TRC_CF(data, cf, "process_pending_input: %zu bytes left " + "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; nread = Curl_bufq_slurp(&ctx->inbufq, nw_in_reader, cf, &result); if(nread != -1) { - DEBUGF(LOG_CF(data, cf, "%zd bytes stray data read before trying " - "h2 connection", nread)); + CURL_TRC_CF(data, cf, "%zd bytes stray data read before trying " + "h2 connection", nread); if(h2_process_pending_input(cf, data, &result) < 0) /* immediate error, considered dead */ 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); if(nwritten < 0) { if(result == CURLE_AGAIN) { - DEBUGF(LOG_CF(data, cf, "flush nw send buffer(%zu) -> EAGAIN", - Curl_bufq_len(&ctx->outbufq))); + CURL_TRC_CF(data, cf, "flush nw send buffer(%zu) -> EAGAIN", + Curl_bufq_len(&ctx->outbufq)); ctx->nw_out_blocked = 1; } 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; } @@ -839,8 +839,8 @@ static int push_promise(struct Curl_cfilter *cf, struct cf_h2_ctx *ctx = cf->ctx; int rv; /* one of the CURL_PUSH_* defines */ - DEBUGF(LOG_CF(data, cf, "[h2sid=%d] PUSH_PROMISE received", - frame->promised_stream_id)); + CURL_TRC_CF(data, cf, "[h2sid=%d] PUSH_PROMISE received", + frame->promised_stream_id); if(data->multi->push_cb) { struct stream_ctx *stream; struct stream_ctx *newstream; @@ -859,7 +859,7 @@ static int push_promise(struct Curl_cfilter *cf, heads.data = data; heads.frame = frame; /* 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); if(!stream) { @@ -931,7 +931,7 @@ static int push_promise(struct Curl_cfilter *cf, } } 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; } fail: @@ -968,20 +968,20 @@ static CURLcode on_stream_frame(struct Curl_cfilter *cf, int rv; 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; } switch(frame->hd.type) { case NGHTTP2_DATA: rbuflen = Curl_bufq_len(&stream->recvbuf); - DEBUGF(LOG_CF(data, cf, "[h2sid=%d] FRAME[DATA len=%zu pad=%zu], " - "buffered=%zu, window=%d/%d", - stream_id, frame->hd.length, frame->data.padlen, rbuflen, - nghttp2_session_get_stream_effective_recv_data_length( - ctx->h2, stream->id), - nghttp2_session_get_stream_effective_local_window_size( - ctx->h2, stream->id))); + CURL_TRC_CF(data, cf, "[h2sid=%d] FRAME[DATA len=%zu pad=%zu], " + "buffered=%zu, window=%d/%d", + stream_id, frame->hd.length, frame->data.padlen, rbuflen, + nghttp2_session_get_stream_effective_recv_data_length( + ctx->h2, stream->id), + nghttp2_session_get_stream_effective_local_window_size( + ctx->h2, stream->id)); /* If !body started on this stream, then receiving DATA is illegal. */ if(!stream->bodystarted) { rv = nghttp2_submit_rst_stream(ctx->h2, NGHTTP2_FLAG_NONE, @@ -1010,7 +1010,7 @@ static CURLcode on_stream_frame(struct Curl_cfilter *cf, } break; 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) { /* Only valid HEADERS after body started is trailer HEADERS. We buffer them in on_header callback. */ @@ -1033,12 +1033,12 @@ static CURLcode on_stream_frame(struct Curl_cfilter *cf, if(result) return result; - DEBUGF(LOG_CF(data, cf, "[h2sid=%d] %zu header bytes", - stream_id, Curl_bufq_len(&stream->recvbuf))); + CURL_TRC_CF(data, cf, "[h2sid=%d] %zu header bytes", + stream_id, Curl_bufq_len(&stream->recvbuf)); drain_stream(cf, data, stream); break; case NGHTTP2_PUSH_PROMISE: - 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); if(rv) { /* deny! */ 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)) return CURLE_SEND_ERROR; else if(rv == CURL_PUSH_ERROROUT) { - DEBUGF(LOG_CF(data, cf, "[h2sid=%d] fail in PUSH_PROMISE received", - stream_id)); + CURL_TRC_CF(data, cf, "[h2sid=%d] fail in PUSH_PROMISE received", + stream_id); return CURLE_RECV_ERROR; } } break; 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->reset = TRUE; stream->send_closed = TRUE; @@ -1063,18 +1063,17 @@ static CURLcode on_stream_frame(struct Curl_cfilter *cf, drain_stream(cf, data, stream); break; 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) && (data->req.keepon & KEEP_SEND)) { data->req.keepon &= ~KEEP_SEND_HOLD; drain_stream(cf, data, stream); - DEBUGF(LOG_CF(data, cf, "[h2sid=%d] un-holding after win update", - stream_id)); + CURL_TRC_CF(data, cf, "[h2sid=%d] un-holding after win update", + stream_id); } break; default: - DEBUGF(LOG_CF(data, cf, "[h2sid=%d] FRAME[%x]", - stream_id, frame->hd.type)); + CURL_TRC_CF(data, cf, "[h2sid=%d] FRAME[%x]", stream_id, frame->hd.type); break; } return CURLE_OK; @@ -1095,19 +1094,19 @@ static int on_frame_recv(nghttp2_session *session, const nghttp2_frame *frame, switch(frame->hd.type) { case NGHTTP2_SETTINGS: { 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( session, NGHTTP2_SETTINGS_MAX_CONCURRENT_STREAMS); ctx->enable_push = nghttp2_session_get_remote_settings( session, NGHTTP2_SETTINGS_ENABLE_PUSH) != 0; - DEBUGF(LOG_CF(data, cf, "MAX_CONCURRENT_STREAMS == %d", - ctx->max_concurrent_streams)); - DEBUGF(LOG_CF(data, cf, "ENABLE_PUSH == %s", - ctx->enable_push ? "TRUE" : "false")); + CURL_TRC_CF(data, cf, "MAX_CONCURRENT_STREAMS == %d", + ctx->max_concurrent_streams); + CURL_TRC_CF(data, cf, "ENABLE_PUSH == %s", + ctx->enable_push ? "TRUE" : "false"); if(data && max_conn != ctx->max_concurrent_streams) { /* only signal change if the value actually changed */ - DEBUGF(LOG_CF(data, cf, "MAX_CONCURRENT_STREAMS now %u", - ctx->max_concurrent_streams)); + CURL_TRC_CF(data, cf, "MAX_CONCURRENT_STREAMS now %u", + ctx->max_concurrent_streams); Curl_multi_connchanged(data->multi); } /* 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; if(stream) { drain_stream(cf, data, stream); - DEBUGF(LOG_CF(data, cf, "[h2sid=%d] un-holding after SETTINGS", - stream_id)); + CURL_TRC_CF(data, cf, "[h2sid=%d] un-holding after SETTINGS", + stream_id); } } 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->last_stream_id = frame->goaway.last_stream_id; if(data) { - DEBUGF(LOG_CF(data, cf, "FRAME[GOAWAY, error=%d, last_stream=%u]", - ctx->goaway_error, ctx->last_stream_id)); + CURL_TRC_CF(data, cf, "FRAME[GOAWAY, error=%d, last_stream=%u]", + ctx->goaway_error, ctx->last_stream_id); infof(data, "received GOAWAY, error=%d, last_stream=%u", ctx->goaway_error, ctx->last_stream_id); Curl_multi_connchanged(data->multi); } break; case NGHTTP2_WINDOW_UPDATE: - DEBUGF(LOG_CF(data, cf, "FRAME[WINDOW_UPDATE]")); + CURL_TRC_CF(data, cf, "FRAME[WINDOW_UPDATE]"); break; 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; } data_s = nghttp2_session_get_stream_user_data(session, stream_id); if(!data_s) { - DEBUGF(LOG_CF(data, cf, "[h2sid=%d] No Curl_easy associated", - stream_id)); + CURL_TRC_CF(data, cf, "[h2sid=%d] No Curl_easy associated", stream_id); 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 we have aborted a transfer artificially and there were more data in the pipeline. Silently ignore. */ - DEBUGF(LOG_CF(CF_DATA_CURRENT(cf), cf, "[h2sid=%d] Data for unknown", - stream_id)); + CURL_TRC_CF(CF_DATA_CURRENT(cf), cf, "[h2sid=%d] Data for unknown", + stream_id); /* consumed explicitly as no one will read it */ nghttp2_session_consume(session, stream_id, len); return 0; @@ -1221,8 +1219,8 @@ static int on_stream_close(nghttp2_session *session, int32_t stream_id, return 0; } stream = H2_STREAM_CTX(data_s); - DEBUGF(LOG_CF(data_s, cf, "[h2sid=%d] on_stream_close(), %s (err %d)", - stream_id, nghttp2_http2_strerror(error_code), error_code)); + CURL_TRC_CF(data_s, cf, "[h2sid=%d] on_stream_close(), %s (err %d)", + stream_id, nghttp2_http2_strerror(error_code), error_code); if(!stream) return NGHTTP2_ERR_CALLBACK_FAILURE; @@ -1241,7 +1239,7 @@ static int on_stream_close(nghttp2_session *session, int32_t stream_id, stream_id); 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; } @@ -1258,7 +1256,7 @@ static int on_begin_headers(nghttp2_session *session, 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) { return 0; @@ -1365,10 +1363,8 @@ static int on_header(nghttp2_session *session, const nghttp2_frame *frame, if(stream->bodystarted) { /* This is a trailer */ - DEBUGF(LOG_CF(data_s, cf, "[h2sid=%d] trailer: %.*s: %.*s", - stream->id, - (int)namelen, name, - (int)valuelen, value)); + CURL_TRC_CF(data_s, cf, "[h2sid=%d] trailer: %.*s: %.*s", + stream->id, (int)namelen, name, (int)valuelen, value); result = Curl_dynhds_add(&stream->resp_trailers, (const char *)name, namelen, (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) Curl_expire(data_s, 0, EXPIRE_RUN_NOW); - DEBUGF(LOG_CF(data_s, cf, "[h2sid=%d] status: HTTP/2 %03d", - stream->id, stream->status_code)); + CURL_TRC_CF(data_s, cf, "[h2sid=%d] status: HTTP/2 %03d", + stream->id, stream->status_code); return 0; } @@ -1429,10 +1425,8 @@ static int on_header(nghttp2_session *session, const nghttp2_frame *frame, if(CF_DATA_CURRENT(cf) != data_s) Curl_expire(data_s, 0, EXPIRE_RUN_NOW); - DEBUGF(LOG_CF(data_s, cf, "[h2sid=%d] header: %.*s: %.*s", - stream->id, - (int)namelen, name, - (int)valuelen, value)); + CURL_TRC_CF(data_s, cf, "[h2sid=%d] header: %.*s: %.*s", + stream->id, (int)namelen, name, (int)valuelen, value); 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) stream->upload_left -= nread; - DEBUGF(LOG_CF(data_s, cf, "[h2sid=%d] req_body_read(len=%zu) left=%" - CURL_FORMAT_CURL_OFF_T " -> %zd, %d", - stream_id, length, stream->upload_left, nread, result)); + CURL_TRC_CF(data_s, cf, "[h2sid=%d] req_body_read(len=%zu) left=%" + CURL_FORMAT_CURL_OFF_T " -> %zd, %d", + stream_id, length, stream->upload_left, nread, result); if(stream->upload_left == 0) *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) 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) { stream->send_closed = TRUE; if(stream->upload_left) { @@ -1578,8 +1572,8 @@ static ssize_t http2_handle_stream_close(struct Curl_cfilter *cf, ssize_t rv = 0; if(stream->error == NGHTTP2_REFUSED_STREAM) { - DEBUGF(LOG_CF(data, cf, "[h2sid=%d] REFUSED_STREAM, try again on a new " - "connection", stream->id)); + CURL_TRC_CF(data, cf, "[h2sid=%d] REFUSED_STREAM, try again on a new " + "connection", stream->id); connclose(cf->conn, "REFUSED_STREAM"); /* don't use this anymore */ data->state.refused_stream = TRUE; *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; 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; } @@ -1697,8 +1691,7 @@ static CURLcode h2_progress_egress(struct Curl_cfilter *cf, nghttp2_priority_spec pri_spec; h2_pri_spec(data, &pri_spec); - DEBUGF(LOG_CF(data, cf, "[h2sid=%d] Queuing PRIORITY", - stream->id)); + CURL_TRC_CF(data, cf, "[h2sid=%d] Queuing PRIORITY", stream->id); DEBUGASSERT(stream->id != -1); rv = nghttp2_submit_priority(ctx->h2, NGHTTP2_FLAG_NONE, stream->id, &pri_spec); @@ -1712,8 +1705,8 @@ static CURLcode h2_progress_egress(struct Curl_cfilter *cf, out: if(nghttp2_is_fatal(rv)) { - DEBUGF(LOG_CF(data, cf, "nghttp2_session_send error (%s)%d", - nghttp2_strerror(rv), rv)); + CURL_TRC_CF(data, cf, "nghttp2_session_send error (%s)%d", + nghttp2_strerror(rv), rv); return CURLE_SEND_ERROR; } 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)) { nread = Curl_bufq_read(&stream->recvbuf, (unsigned char *)buf, len, err); - DEBUGF(LOG_CF(data, cf, "recvbuf read(len=%zu) -> %zd, %d", - len, nread, *err)); + CURL_TRC_CF(data, cf, "recvbuf read(len=%zu) -> %zd, %d", + len, nread, *err); if(nread < 0) goto out; DEBUGASSERT(nread > 0); @@ -1739,13 +1732,13 @@ static ssize_t stream_recv(struct Curl_cfilter *cf, struct Curl_easy *data, if(nread < 0) { 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); } else if(stream->reset || (ctx->conn_closed && Curl_bufq_is_empty(&ctx->inbufq)) || (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; nread = -1; } @@ -1756,8 +1749,7 @@ static ssize_t stream_recv(struct Curl_cfilter *cf, struct Curl_easy *data, } out: - DEBUGF(LOG_CF(data, cf, "stream_recv(len=%zu) -> %zd, %d", - len, nread, *err)); + CURL_TRC_CF(data, cf, "stream_recv(len=%zu) -> %zd, %d", len, nread, *err); return nread; } @@ -1771,8 +1763,8 @@ static CURLcode h2_progress_ingress(struct Curl_cfilter *cf, /* Process network input buffer fist */ if(!Curl_bufq_is_empty(&ctx->inbufq)) { - DEBUGF(LOG_CF(data, cf, "Process %zu bytes in connection buffer", - Curl_bufq_len(&ctx->inbufq))); + CURL_TRC_CF(data, cf, "Process %zu bytes in connection buffer", + Curl_bufq_len(&ctx->inbufq)); if(h2_process_pending_input(cf, data, &result) < 0) 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); - /* DEBUGF(LOG_CF(data, cf, "read %zu bytes nw data -> %zd, %d", - Curl_bufq_len(&ctx->inbufq), nread, result)); */ if(nread < 0) { if(result != CURLE_AGAIN) { 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) { - DEBUGF(LOG_CF(data, cf, "[h2sid=%d] closed stream, set drain", - stream->id)); + CURL_TRC_CF(data, cf, "[h2sid=%d] closed stream, set drain", stream->id); drain_stream(cf, data, stream); } } @@ -1884,16 +1873,16 @@ out: *err = result; nread = -1; } - DEBUGF(LOG_CF(data, cf, "[h2sid=%d] cf_recv(len=%zu) -> %zd %d, " - "buffered=%zu, window=%d/%d, connection %d/%d", - stream->id, len, nread, *err, - Curl_bufq_len(&stream->recvbuf), - nghttp2_session_get_stream_effective_recv_data_length( - ctx->h2, stream->id), - nghttp2_session_get_stream_effective_local_window_size( - ctx->h2, stream->id), - nghttp2_session_get_local_window_size(ctx->h2), - HTTP2_HUGE_WINDOW_SIZE)); + CURL_TRC_CF(data, cf, "[h2sid=%d] cf_recv(len=%zu) -> %zd %d, " + "buffered=%zu, window=%d/%d, connection %d/%d", + stream->id, len, nread, *err, + Curl_bufq_len(&stream->recvbuf), + nghttp2_session_get_stream_effective_recv_data_length( + ctx->h2, stream->id), + nghttp2_session_get_stream_effective_local_window_size( + ctx->h2, stream->id), + nghttp2_session_get_local_window_size(ctx->h2), + HTTP2_HUGE_WINDOW_SIZE); CF_DATA_RESTORE(cf, save); return nread; @@ -1974,8 +1963,8 @@ static ssize_t h2_submit(struct stream_ctx **pstream, h2_pri_spec(data, &pri_spec); - DEBUGF(LOG_CF(data, cf, "send request allowed %d", - nghttp2_session_check_request_allowed(ctx->h2))); + CURL_TRC_CF(data, cf, "send request allowed %d", + nghttp2_session_check_request_allowed(ctx->h2)); switch(data->state.httpreq) { case HTTPREQ_POST: @@ -2002,15 +1991,15 @@ static ssize_t h2_submit(struct stream_ctx **pstream, Curl_safefree(nva); if(stream_id < 0) { - DEBUGF(LOG_CF(data, cf, "send: nghttp2_submit_request error (%s)%u", - nghttp2_strerror(stream_id), stream_id)); + CURL_TRC_CF(data, cf, "send: nghttp2_submit_request error (%s)%u", + nghttp2_strerror(stream_id), stream_id); *err = CURLE_SEND_ERROR; nwritten = -1; goto out; } - DEBUGF(LOG_CF(data, cf, "[h2sid=%d] cf_send(len=%zu) submit %s", - stream_id, len, data->state.url)); + CURL_TRC_CF(data, cf, "[h2sid=%d] cf_send(len=%zu) submit %s", + stream_id, len, data->state.url); infof(data, "Using Stream ID: %u", stream_id); stream->id = stream_id; stream->local_window_size = H2_STREAM_WINDOW_SIZE; @@ -2042,8 +2031,8 @@ static ssize_t h2_submit(struct stream_ctx **pstream, } out: - DEBUGF(LOG_CF(data, cf, "[h2sid=%d] submit -> %zd, %d", - stream? stream->id : -1, nwritten, *err)); + CURL_TRC_CF(data, cf, "[h2sid=%d] submit -> %zd, %d", + stream? stream->id : -1, nwritten, *err); *pstream = stream; Curl_h1_req_parse_free(&h1); 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 * a WINDOW_UPDATE from the server. */ data->req.keepon |= KEEP_SEND_HOLD; - DEBUGF(LOG_CF(data, cf, "[h2sid=%d] holding send as remote flow " - "window is exhausted", stream->id)); + CURL_TRC_CF(data, cf, "[h2sid=%d] holding send as remote flow " + "window is exhausted", stream->id); } /* Whatever the cause, we need to return CURL_EAGAIN for this call. * We have unwritten state that needs us being invoked again and EAGAIN * is the only way to ensure that. */ stream->upload_blocked_len = nwritten; - DEBUGF(LOG_CF(data, cf, "[h2sid=%d] cf_send(len=%zu) BLOCK: win %u/%zu " - "blocked_len=%zu", - stream->id, len, - nghttp2_session_get_remote_window_size(ctx->h2), rwin, - nwritten)); + CURL_TRC_CF(data, cf, "[h2sid=%d] cf_send(len=%zu) BLOCK: win %u/%zu " + "blocked_len=%zu", + stream->id, len, + nghttp2_session_get_remote_window_size(ctx->h2), rwin, + nwritten); *err = CURLE_AGAIN; nwritten = -1; 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); } 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; nwritten = -1; } @@ -2187,24 +2176,24 @@ static ssize_t cf_h2_send(struct Curl_cfilter *cf, struct Curl_easy *data, out: if(stream) { - DEBUGF(LOG_CF(data, cf, "[h2sid=%d] cf_send(len=%zu) -> %zd, %d, " - "upload_left=%" CURL_FORMAT_CURL_OFF_T ", " - "h2 windows %d-%d (stream-conn), " - "buffers %zu-%zu (stream-conn)", - stream->id, len, nwritten, *err, - (ssize_t)stream->upload_left, - nghttp2_session_get_stream_remote_window_size( - ctx->h2, stream->id), - nghttp2_session_get_remote_window_size(ctx->h2), - Curl_bufq_len(&stream->sendbuf), - Curl_bufq_len(&ctx->outbufq))); + CURL_TRC_CF(data, cf, "[h2sid=%d] cf_send(len=%zu) -> %zd, %d, " + "upload_left=%" CURL_FORMAT_CURL_OFF_T ", " + "h2 windows %d-%d (stream-conn), " + "buffers %zu-%zu (stream-conn)", + stream->id, len, nwritten, *err, + (ssize_t)stream->upload_left, + nghttp2_session_get_stream_remote_window_size( + ctx->h2, stream->id), + nghttp2_session_get_remote_window_size(ctx->h2), + Curl_bufq_len(&stream->sendbuf), + Curl_bufq_len(&ctx->outbufq)); } else { - DEBUGF(LOG_CF(data, cf, "cf_send(len=%zu) -> %zd, %d, " - "connection-window=%d, nw_send_buffer(%zu)", - len, nwritten, *err, - nghttp2_session_get_remote_window_size(ctx->h2), - Curl_bufq_len(&ctx->outbufq))); + CURL_TRC_CF(data, cf, "cf_send(len=%zu) -> %zd, %d, " + "connection-window=%d, nw_send_buffer(%zu)", + len, nwritten, *err, + nghttp2_session_get_remote_window_size(ctx->h2), + Curl_bufq_len(&ctx->outbufq)); } CF_DATA_RESTORE(cf, save); return nwritten; @@ -2421,8 +2410,8 @@ static bool cf_h2_is_alive(struct Curl_cfilter *cf, CF_DATA_SAVE(save, cf, data); result = (ctx && ctx->h2 && http2_connisalive(cf, data, input_pending)); - DEBUGF(LOG_CF(data, cf, "conn alive -> %d, input_pending=%d", - result, *input_pending)); + CURL_TRC_CF(data, cf, "conn alive -> %d, input_pending=%d", + result, *input_pending); CF_DATA_RESTORE(cf, save); return result; } @@ -2473,7 +2462,7 @@ static CURLcode cf_h2_query(struct Curl_cfilter *cf, struct Curl_cftype Curl_cft_nghttp2 = { "HTTP/2", CF_TYPE_MULTIPLEX, - CURL_LOG_DEFAULT, + CURL_LOG_LVL_NONE, cf_h2_destroy, cf_h2_connect, cf_h2_close, diff --git a/lib/http_proxy.c b/lib/http_proxy.c index 4fd998a0c3..60bbfbe580 100644 --- a/lib/http_proxy.c +++ b/lib/http_proxy.c @@ -69,7 +69,7 @@ static CURLcode http_proxy_cf_connect(struct Curl_cfilter *cf, return CURLE_OK; } - DEBUGF(LOG_CF(data, cf, "connect")); + CURL_TRC_CF(data, cf, "connect"); connect_sub: result = cf->next->cft->do_connect(cf->next, data, blocking, done); if(result || !*done) @@ -86,7 +86,7 @@ connect_sub: case CURL_HTTP_VERSION_NONE: case CURL_HTTP_VERSION_1_0: 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", (alpn == CURL_HTTP_VERSION_1_0)? 0 : 1); result = Curl_cf_h1_proxy_insert_after(cf, data); @@ -96,7 +96,7 @@ connect_sub: break; #ifdef USE_NGHTTP2 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"); result = Curl_cf_h2_proxy_insert_after(cf, data); if(result) @@ -105,7 +105,7 @@ connect_sub: break; #endif 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); result = CURLE_COULDNT_CONNECT; goto out; @@ -156,7 +156,7 @@ static void http_proxy_cf_destroy(struct Curl_cfilter *cf, struct cf_proxy_ctx *ctx = cf->ctx; (void)data; - DEBUGF(LOG_CF(data, cf, "destroy")); + CURL_TRC_CF(data, cf, "destroy"); free(ctx); } @@ -165,7 +165,7 @@ static void http_proxy_cf_close(struct Curl_cfilter *cf, { struct cf_proxy_ctx *ctx = cf->ctx; - DEBUGF(LOG_CF(data, cf, "close")); + CURL_TRC_CF(data, cf, "close"); cf->connected = FALSE; if(ctx->cf_protocol) { struct Curl_cfilter *f; diff --git a/lib/rand.c b/lib/rand.c index 7d24765ccd..3e6bce0729 100644 --- a/lib/rand.c +++ b/lib/rand.c @@ -36,6 +36,7 @@ uint32_t arc4random(void); #endif #include +#include "urldata.h" #include "vtls/vtls.h" #include "sendf.h" #include "timeval.h" diff --git a/lib/sendf.h b/lib/sendf.h index d0c9275705..25881efa88 100644 --- a/lib/sendf.h +++ b/lib/sendf.h @@ -26,7 +26,7 @@ #include "curl_setup.h" -#include "curl_log.h" +#include "curl_trc.h" #define CLIENTWRITE_BODY (1<<0) diff --git a/lib/url.c b/lib/url.c index 1d6f2fad42..3c9bee1d73 100644 --- a/lib/url.c +++ b/lib/url.c @@ -1494,13 +1494,7 @@ void Curl_verboseconnect(struct Curl_easy *data, { if(data->set.verbose) infof(data, "Connected to %s (%s) port %u", -#ifndef CURL_DISABLE_PROXY - 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); + CURL_CONN_HOST_DISPNAME(conn), conn->primary_ip, conn->port); } #endif diff --git a/lib/urldata.h b/lib/urldata.h index d21aa415dc..21e9daeffd 100644 --- a/lib/urldata.h +++ b/lib/urldata.h @@ -1076,6 +1076,18 @@ struct connectdata { 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. */ /* diff --git a/lib/vquic/curl_msh3.c b/lib/vquic/curl_msh3.c index 02b5334f28..6bd0d23316 100644 --- a/lib/vquic/curl_msh3.c +++ b/lib/vquic/curl_msh3.c @@ -30,7 +30,7 @@ #include "timeval.h" #include "multiif.h" #include "sendf.h" -#include "curl_log.h" +#include "curl_trc.h" #include "cfilters.h" #include "cf-socket.h" #include "connect.h" @@ -173,7 +173,7 @@ static CURLcode h3_data_setup(struct Curl_cfilter *cf, msh3_lock_initialize(&stream->recv_lock); Curl_bufq_init2(&stream->recvbuf, H3_STREAM_CHUNK_SIZE, 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; } @@ -183,7 +183,7 @@ static void h3_data_done(struct Curl_cfilter *cf, struct Curl_easy *data) (void)cf; 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); free(stream); 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); (void)Connection; - DEBUGF(LOG_CF(data, cf, "[MSH3] connected")); + CURL_TRC_CF(data, cf, "[MSH3] connected"); ctx->handshake_succeeded = true; ctx->connected = 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); (void)Connection; - DEBUGF(LOG_CF(data, cf, "[MSH3] shutdown complete")); + CURL_TRC_CF(data, cf, "[MSH3] shutdown complete"); ctx->connected = false; ctx->handshake_complete = true; } @@ -474,18 +474,18 @@ static ssize_t recv_closed_stream(struct Curl_cfilter *cf, if(stream->reset) { failf(data, "HTTP/3 stream reset by server"); *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; } else if(stream->error3) { failf(data, "HTTP/3 stream was not closed cleanly: (error %zd)", (ssize_t)stream->error3); *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; } 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; nread = 0; @@ -523,7 +523,7 @@ static ssize_t cf_msh3_recv(struct Curl_cfilter *cf, struct Curl_easy *data, return -1; } 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); @@ -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)) { nread = Curl_bufq_read(&stream->recvbuf, (unsigned char *)buf, len, err); - DEBUGF(LOG_CF(data, cf, "read recvbuf(len=%zu) -> %zd, %d", - len, nread, *err)); + CURL_TRC_CF(data, cf, "read recvbuf(len=%zu) -> %zd, %d", + len, nread, *err); if(nread < 0) goto out; if(stream->closed) @@ -550,7 +550,7 @@ static ssize_t cf_msh3_recv(struct Curl_cfilter *cf, struct Curl_easy *data, goto out; } else { - DEBUGF(LOG_CF(data, cf, "req: nothing here, call again")); + CURL_TRC_CF(data, cf, "req: nothing here, call 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" */ 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) { /* 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; } - 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, nva, nheader, eos ? MSH3_REQUEST_FLAG_FIN : @@ -646,7 +646,7 @@ static ssize_t cf_msh3_send(struct Curl_cfilter *cf, struct Curl_easy *data, } else { /* 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) { len = 0xFFFFFFFF; } @@ -694,7 +694,7 @@ static int cf_msh3_get_select_socks(struct Curl_cfilter *cf, 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); return bitmap; } @@ -711,8 +711,8 @@ static bool cf_msh3_data_pending(struct Curl_cfilter *cf, (void)cf; if(stream && stream->req) { msh3_lock_acquire(&stream->recv_lock); - DEBUGF(LOG_CF((struct Curl_easy *)data, cf, "data pending = %zu", - Curl_bufq_len(&stream->recvbuf))); + CURL_TRC_CF((struct Curl_easy *)data, cf, "data pending = %zu", + Curl_bufq_len(&stream->recvbuf)); pending = !Curl_bufq_is_empty(&stream->recvbuf); msh3_lock_release(&stream->recv_lock); if(pending) @@ -774,7 +774,7 @@ static CURLcode cf_msh3_data_event(struct Curl_cfilter *cf, h3_data_done(cf, data); break; case CF_CTRL_DATA_DONE_SEND: - DEBUGF(LOG_CF(data, cf, "req: send done")); + CURL_TRC_CF(data, cf, "req: send done"); if(stream) { stream->upload_done = TRUE; if(stream->req) { @@ -787,7 +787,7 @@ static CURLcode cf_msh3_data_event(struct Curl_cfilter *cf, } break; 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); break; default: @@ -813,17 +813,17 @@ static CURLcode cf_connect_start(struct Curl_cfilter *cf, /* TODO: need a way to provide trust anchors to MSH3 */ #ifdef DEBUGBUILD /* we need this for our test cases to run */ - DEBUGF(LOG_CF(data, cf, "non-standard CA not supported, " - "switching off verifypeer in DEBUG mode")); + CURL_TRC_CF(data, cf, "non-standard CA not supported, " + "switching off verifypeer in DEBUG mode"); verify = 0; #else - DEBUGF(LOG_CF(data, cf, "non-standard CA not supported, " - "attempting with built-in verification")); + CURL_TRC_CF(data, cf, "non-standard CA not supported, " + "attempting with built-in verification"); #endif } - DEBUGF(LOG_CF(data, cf, "connecting to %s:%d (verify=%d)", - cf->conn->host.name, (int)cf->conn->remote_port, verify)); + CURL_TRC_CF(data, cf, "connecting to %s:%d (verify=%d)", + cf->conn->host.name, (int)cf->conn->remote_port, verify); ctx->api = MsH3ApiOpen(); if(!ctx->api) { @@ -888,7 +888,7 @@ static CURLcode cf_msh3_connect(struct Curl_cfilter *cf, if(ctx->handshake_complete) { ctx->handshake_at = Curl_now(); 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->httpversion = 30; 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); if(ctx) { - DEBUGF(LOG_CF(data, cf, "destroying")); + CURL_TRC_CF(data, cf, "destroying"); if(ctx->qconn) { MsH3ConnectionClose(ctx->qconn); ctx->qconn = NULL; @@ -935,13 +935,13 @@ static void cf_msh3_close(struct Curl_cfilter *cf, struct Curl_easy *data) */ ctx->active = FALSE; if(ctx->sock[SP_LOCAL] == cf->conn->sock[cf->sockindex]) { - DEBUGF(LOG_CF(data, cf, "cf_msh3_close(%d) active", - (int)ctx->sock[SP_LOCAL])); + CURL_TRC_CF(data, cf, "cf_msh3_close(%d) active", + (int)ctx->sock[SP_LOCAL]); cf->conn->sock[cf->sockindex] = CURL_SOCKET_BAD; } else { - DEBUGF(LOG_CF(data, cf, "cf_socket_close(%d) no longer at " - "conn->sock[], discarding", (int)ctx->sock[SP_LOCAL])); + CURL_TRC_CF(data, cf, "cf_socket_close(%d) no longer at " + "conn->sock[], discarding", (int)ctx->sock[SP_LOCAL]); ctx->sock[SP_LOCAL] = CURL_SOCKET_BAD; } if(cf->sockindex == FIRSTSOCKET) diff --git a/lib/vquic/curl_ngtcp2.c b/lib/vquic/curl_ngtcp2.c index a430aa119a..f58b685f6c 100644 --- a/lib/vquic/curl_ngtcp2.c +++ b/lib/vquic/curl_ngtcp2.c @@ -225,7 +225,7 @@ static CURLcode h3_data_setup(struct Curl_cfilter *cf, stream->recv_buf_nonflow = 0; H3_STREAM_LCTX(data) = stream; - DEBUGF(LOG_CF(data, cf, "data setup")); + CURL_TRC_CF(data, cf, "data setup"); return CURLE_OK; } @@ -235,8 +235,7 @@ static void h3_data_done(struct Curl_cfilter *cf, struct Curl_easy *data) (void)cf; if(stream) { - DEBUGF(LOG_CF(data, cf, "[h3sid=%"PRId64"] easy handle is done", - stream->id)); + CURL_TRC_CF(data, cf, "[h3sid=%"PRId64"] easy handle is done", stream->id); Curl_bufq_free(&stream->sendbuf); Curl_bufq_free(&stream->recvbuf); 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); if(ngtcp2_crypto_gnutls_configure_client_session(ctx->gtls->session) != 0) { - DEBUGF(LOG_CF(data, cf, - "ngtcp2_crypto_gnutls_configure_client_session failed\n")); + CURL_TRC_CF(data, cf, + "ngtcp2_crypto_gnutls_configure_client_session failed\n"); return CURLE_QUIC_CONNECT_ERROR; } rc = gnutls_priority_set_direct(ctx->gtls->session, QUIC_PRIORITY, NULL); if(rc < 0) { - DEBUGF(LOG_CF(data, cf, "gnutls_priority_set_direct failed: %s\n", - gnutls_strerror(rc))); + CURL_TRC_CF(data, cf, "gnutls_priority_set_direct failed: %s\n", + gnutls_strerror(rc)); return CURLE_QUIC_CONNECT_ERROR; } @@ -728,8 +727,8 @@ static void report_consumed_data(struct Curl_cfilter *cf, } } if(consumed > 0) { - DEBUGF(LOG_CF(data, cf, "[h3sid=%" PRId64 "] consumed %zu DATA bytes", - stream->id, consumed)); + CURL_TRC_CF(data, cf, "[h3sid=%" PRId64 "] consumed %zu DATA bytes", + stream->id, consumed); ngtcp2_conn_extend_max_stream_offset(ctx->qconn, stream->id, 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 = nghttp3_conn_read_stream(ctx->h3conn, stream_id, buf, buflen, fin); - DEBUGF(LOG_CF(data, cf, "[h3sid=%" PRId64 "] read_stream(len=%zu) -> %zd", - stream_id, buflen, nconsumed)); + CURL_TRC_CF(data, cf, "[h3sid=%" PRId64 "] read_stream(len=%zu) -> %zd", + stream_id, buflen, nconsumed); if(nconsumed < 0) { ngtcp2_ccerr_set_application_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, app_error_code); - DEBUGF(LOG_CF(data, cf, "[h3sid=%" PRId64 "] quic close(err=%" - PRIu64 ") -> %d", stream3_id, app_error_code, rv)); + CURL_TRC_CF(data, cf, "[h3sid=%" PRId64 "] quic close(err=%" + PRIu64 ") -> %d", stream3_id, app_error_code, rv); if(rv) { ngtcp2_ccerr_set_application_error( &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; 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) { 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)) rv |= GETSOCK_WRITESOCK(0); - /* DEBUGF(LOG_CF(data, cf, "get_select_socks -> %x (sock=%d)", - rv, (int)socks[0])); */ CF_DATA_RESTORE(cf, save); return rv; } @@ -1102,8 +1099,8 @@ static int cb_h3_stream_close(nghttp3_conn *conn, int64_t stream_id, if(!stream) return 0; - DEBUGF(LOG_CF(data, cf, "[h3sid=%" PRId64 "] h3 close(err=%" PRId64 ")", - stream_id, app_error_code)); + CURL_TRC_CF(data, cf, "[h3sid=%" PRId64 "] h3 close(err=%" PRId64 ")", + stream_id, app_error_code); stream->closed = TRUE; stream->error3 = app_error_code; 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; } 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) { return result; } @@ -1204,8 +1198,8 @@ static int cb_h3_end_headers(nghttp3_conn *conn, int64_t stream_id, return -1; } - DEBUGF(LOG_CF(data, cf, "[h3sid=%" PRId64 "] end_headers(status_code=%d", - stream_id, stream->status_code)); + CURL_TRC_CF(data, cf, "[h3sid=%" PRId64 "] end_headers(status_code=%d", + stream_id, stream->status_code); if(stream->status_code / 100 != 1) { stream->resp_hds_complete = TRUE; } @@ -1244,8 +1238,7 @@ static int cb_h3_recv_header(nghttp3_conn *conn, int64_t stream_id, return -1; ncopy = msnprintf(line, sizeof(line), "HTTP/3 %03d \r\n", stream->status_code); - DEBUGF(LOG_CF(data, cf, "[h3sid=%" PRId64 "] status: %s", - stream_id, line)); + CURL_TRC_CF(data, cf, "[h3sid=%" PRId64 "] status: %s", stream_id, line); result = write_resp_raw(cf, data, line, ncopy, FALSE); if(result) { return -1; @@ -1253,9 +1246,9 @@ static int cb_h3_recv_header(nghttp3_conn *conn, int64_t stream_id, } else { /* store as an HTTP1-style header */ - DEBUGF(LOG_CF(data, cf, "[h3sid=%" PRId64 "] header: %.*s: %.*s", - stream_id, (int)h3name.len, h3name.base, - (int)h3val.len, h3val.base)); + CURL_TRC_CF(data, cf, "[h3sid=%" PRId64 "] header: %.*s: %.*s", + stream_id, (int)h3name.len, h3name.base, + (int)h3val.len, h3val.base); result = write_resp_raw(cf, data, h3name.base, h3name.len, FALSE); if(result) { 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, 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) { return NGTCP2_ERR_CALLBACK_FAILURE; } @@ -1405,8 +1398,8 @@ static ssize_t recv_closed_stream(struct Curl_cfilter *cf, failf(data, "HTTP/3 stream %" PRId64 " reset by server", stream->id); *err = CURLE_PARTIAL_FILE; - DEBUGF(LOG_CF(data, cf, "[h3sid=%" PRId64 "] cf_recv, was reset -> %d", - stream->id, *err)); + CURL_TRC_CF(data, cf, "[h3sid=%" PRId64 "] cf_recv, was reset -> %d", + stream->id, *err); goto out; } 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: " "(err %"PRId64")", stream->id, stream->error3); *err = CURLE_HTTP3; - DEBUGF(LOG_CF(data, cf, "[h3sid=%" PRId64 "] cf_recv, closed uncleanly" - " -> %d", stream->id, *err)); + CURL_TRC_CF(data, cf, "[h3sid=%" PRId64 "] cf_recv, closed uncleanly" + " -> %d", stream->id, *err); goto out; } @@ -1425,13 +1418,13 @@ static ssize_t recv_closed_stream(struct Curl_cfilter *cf, " all response header fields, treated as error", stream->id); *err = CURLE_HTTP3; - DEBUGF(LOG_CF(data, cf, "[h3sid=%" PRId64 "] cf_recv, closed incomplete" - " -> %d", stream->id, *err)); + CURL_TRC_CF(data, cf, "[h3sid=%" PRId64 "] cf_recv, closed incomplete" + " -> %d", stream->id, *err); goto out; } else { - DEBUGF(LOG_CF(data, cf, "[h3sid=%" PRId64 "] cf_recv, closed ok" - " -> %d", stream->id, *err)); + CURL_TRC_CF(data, cf, "[h3sid=%" PRId64 "] cf_recv, closed ok" + " -> %d", stream->id, *err); } *err = CURLE_OK; 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)) { nread = Curl_bufq_read(&stream->recvbuf, (unsigned char *)buf, len, err); - DEBUGF(LOG_CF(data, cf, "[h3sid=%" PRId64 "] read recvbuf(len=%zu) " - "-> %zd, %d", stream->id, len, nread, *err)); + CURL_TRC_CF(data, cf, "[h3sid=%" PRId64 "] read recvbuf(len=%zu) " + "-> %zd, %d", stream->id, len, nread, *err); if(nread < 0) goto out; 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)) { nread = Curl_bufq_read(&stream->recvbuf, (unsigned char *)buf, len, err); - DEBUGF(LOG_CF(data, cf, "[h3sid=%" PRId64 "] read recvbuf(len=%zu) " - "-> %zd, %d", stream->id, len, nread, *err)); + CURL_TRC_CF(data, cf, "[h3sid=%" PRId64 "] read recvbuf(len=%zu) " + "-> %zd, %d", stream->id, len, nread, *err); if(nread < 0) goto out; report_consumed_data(cf, data, nread); @@ -1517,8 +1510,8 @@ out: nread = -1; } } - DEBUGF(LOG_CF(data, cf, "[h3sid=%" PRId64 "] cf_recv(len=%zu) -> %zd, %d", - stream? stream->id : -1, len, nread, *err)); + CURL_TRC_CF(data, cf, "[h3sid=%" PRId64 "] cf_recv(len=%zu) -> %zd, %d", + stream? stream->id : -1, len, nread, *err); CF_DATA_RESTORE(cf, save); 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_HOLD; h3_drain_stream(cf, data); - DEBUGF(LOG_CF(data, cf, "[h3sid=%" PRId64 "] unpausing acks", - stream_id)); + CURL_TRC_CF(data, cf, "[h3sid=%" PRId64 "] unpausing acks", stream_id); } } return 0; @@ -1613,18 +1605,18 @@ cb_h3_read_req_body(nghttp3_conn *conn, int64_t stream_id, } else if(!nwritten) { /* Not EOF, and nothing to give, we signal WOULDBLOCK. */ - DEBUGF(LOG_CF(data, cf, "[h3sid=%" PRId64 "] read req body -> AGAIN", - stream->id)); + CURL_TRC_CF(data, cf, "[h3sid=%" PRId64 "] read req body -> AGAIN", + stream->id); return NGHTTP3_ERR_WOULDBLOCK; } - DEBUGF(LOG_CF(data, cf, "[h3sid=%" PRId64 "] read req body -> " - "%d vecs%s with %zu (buffered=%zu, left=%" - CURL_FORMAT_CURL_OFF_T ")", - stream->id, (int)nvecs, - *pflags == NGHTTP3_DATA_FLAG_EOF?" EOF":"", - nwritten, Curl_bufq_len(&stream->sendbuf), - stream->upload_left)); + CURL_TRC_CF(data, cf, "[h3sid=%" PRId64 "] read req body -> " + "%d vecs%s with %zu (buffered=%zu, left=%" + CURL_FORMAT_CURL_OFF_T ")", + stream->id, (int)nvecs, + *pflags == NGHTTP3_DATA_FLAG_EOF?" EOF":"", + nwritten, Curl_bufq_len(&stream->sendbuf), + stream->upload_left); return (nghttp3_ssize)nvecs; } @@ -1723,12 +1715,12 @@ static ssize_t h3_stream_open(struct Curl_cfilter *cf, if(rc) { switch(rc) { case NGHTTP3_ERR_CONN_CLOSING: - DEBUGF(LOG_CF(data, cf, "h3sid[%"PRId64"] failed to send, " - "connection is closing", stream->id)); + CURL_TRC_CF(data, cf, "h3sid[%"PRId64"] failed to send, " + "connection is closing", stream->id); break; default: - DEBUGF(LOG_CF(data, cf, "h3sid[%"PRId64"] failed to send -> %d (%s)", - stream->id, rc, ngtcp2_strerror(rc))); + CURL_TRC_CF(data, cf, "h3sid[%"PRId64"] failed to send -> %d (%s)", + stream->id, rc, ngtcp2_strerror(rc)); break; } *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); - DEBUGF(LOG_CF(data, cf, "[h3sid=%" PRId64 "] opened for %s", - stream->id, data->state.url)); + CURL_TRC_CF(data, cf, "[h3sid=%" PRId64 "] opened for %s", + stream->id, data->state.url); out: 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) { sent = h3_stream_open(cf, data, buf, len, err); 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; } } @@ -1799,9 +1791,9 @@ static ssize_t cf_ngtcp2_send(struct Curl_cfilter *cf, struct Curl_easy *data, } else { sent = Curl_bufq_write(&stream->sendbuf, buf, len, err); - DEBUGF(LOG_CF(data, cf, "[h3sid=%" PRId64 "] cf_send, add to " - "sendbuf(len=%zu) -> %zd, %d", - stream->id, len, sent, *err)); + CURL_TRC_CF(data, cf, "[h3sid=%" PRId64 "] cf_send, add to " + "sendbuf(len=%zu) -> %zd, %d", + stream->id, len, sent, *err); if(sent < 0) { 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. * We put the stream upload on HOLD, until this gets ACKed. */ stream->upload_blocked_len = sent; - DEBUGF(LOG_CF(data, cf, "[h3sid=%" PRId64 "] cf_send(len=%zu), " - "%zu bytes in flight -> EGAIN", stream->id, len, - stream->sendbuf_len_in_flight)); + CURL_TRC_CF(data, cf, "[h3sid=%" PRId64 "] cf_send(len=%zu), " + "%zu bytes in flight -> EGAIN", stream->id, len, + stream->sendbuf_len_in_flight); *err = CURLE_AGAIN; sent = -1; data->req.keepon |= KEEP_SEND_HOLD; @@ -1835,8 +1827,8 @@ out: *err = result; sent = -1; } - DEBUGF(LOG_CF(data, cf, "[h3sid=%" PRId64 "] cf_send(len=%zu) -> %zd, %d", - stream? stream->id : -1, len, sent, *err)); + CURL_TRC_CF(data, cf, "[h3sid=%" PRId64 "] cf_send(len=%zu) -> %zd, %d", + stream? stream->id : -1, len, sent, *err); CF_DATA_RESTORE(cf, save); 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); if(rv) { - DEBUGF(LOG_CF(pktx->data, pktx->cf, "ingress, read_pkt -> %s", - ngtcp2_strerror(rv))); + CURL_TRC_CF(pktx->data, pktx->cf, "ingress, read_pkt -> %s", + ngtcp2_strerror(rv)); if(!ctx->last_error.error_code) { if(rv == NGTCP2_ERR_CRYPTO) { 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 */ nread = Curl_bufq_sipn(&ctx->q.sendbuf, max_payload_size, 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(curlcode != CURLE_AGAIN) return curlcode; @@ -2305,7 +2295,7 @@ static void cf_ngtcp2_close(struct Curl_cfilter *cf, struct Curl_easy *data) ngtcp2_tstamp ts; ngtcp2_ssize rc; - DEBUGF(LOG_CF(data, cf, "close")); + CURL_TRC_CF(data, cf, "close"); ts = timestamp(); rc = ngtcp2_conn_write_connection_close(ctx->qconn, NULL, /* path */ 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; CF_DATA_SAVE(save, cf, data); - DEBUGF(LOG_CF(data, cf, "destroy")); + CURL_TRC_CF(data, cf, "destroy"); if(ctx) { cf_ngtcp2_ctx_clear(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) { /* 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; } @@ -2484,11 +2474,11 @@ static CURLcode cf_ngtcp2_connect(struct Curl_cfilter *cf, if(ngtcp2_conn_get_handshake_completed(ctx->qconn)) { ctx->handshake_at = now; - DEBUGF(LOG_CF(data, cf, "handshake complete after %dms", - (int)Curl_timediff(now, ctx->started_at))); + CURL_TRC_CF(data, cf, "handshake complete after %dms", + (int)Curl_timediff(now, ctx->started_at)); result = qng_verify_peer(cf, data); if(!result) { - DEBUGF(LOG_CF(data, cf, "peer verified")); + CURL_TRC_CF(data, cf, "peer verified"); cf->connected = TRUE; cf->conn->alpn = CURL_HTTP_VERSION_3; *done = TRUE; @@ -2510,8 +2500,8 @@ out: */ int reconn_delay_ms = 200; - DEBUGF(LOG_CF(data, cf, "connect, remote closed, reconnect after %dms", - reconn_delay_ms)); + CURL_TRC_CF(data, cf, "connect, remote closed, reconnect after %dms", + reconn_delay_ms); Curl_conn_cf_close(cf->next, data); cf_ngtcp2_ctx_clear(ctx); result = Curl_conn_cf_connect(cf->next, data, FALSE, done); @@ -2538,7 +2528,7 @@ out: if(!result && ctx->qconn) { 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); return result; } @@ -2562,7 +2552,7 @@ static CURLcode cf_ngtcp2_query(struct Curl_cfilter *cf, INT_MAX : (int)rp->initial_max_streams_bidi; else /* not arrived yet? */ *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); return CURLE_OK; } diff --git a/lib/vquic/curl_quiche.c b/lib/vquic/curl_quiche.c index 39cc16e944..c3c20eece2 100644 --- a/lib/vquic/curl_quiche.c +++ b/lib/vquic/curl_quiche.c @@ -217,11 +217,10 @@ static void stream_send_suspend(struct Curl_cfilter *cf, data->req.keepon |= KEEP_SEND_HOLD; ++ctx->sends_on_hold; if(H3_STREAM_ID(data) >= 0) - DEBUGF(LOG_CF(data, cf, "[h3sid=%"PRId64"] suspend sending", - H3_STREAM_ID(data))); + CURL_TRC_CF(data, cf, "[h3sid=%"PRId64"] suspend sending", + H3_STREAM_ID(data)); else - DEBUGF(LOG_CF(data, cf, "[%s] suspend sending", - data->state.url)); + CURL_TRC_CF(data, cf, "[%s] suspend sending", data->state.url); } } @@ -234,11 +233,10 @@ static void stream_send_resume(struct Curl_cfilter *cf, data->req.keepon &= ~KEEP_SEND_HOLD; --ctx->sends_on_hold; if(H3_STREAM_ID(data) >= 0) - DEBUGF(LOG_CF(data, cf, "[h3sid=%"PRId64"] resume sending", - H3_STREAM_ID(data))); + CURL_TRC_CF(data, cf, "[h3sid=%"PRId64"] resume sending", + H3_STREAM_ID(data)); else - DEBUGF(LOG_CF(data, cf, "[%s] resume sending", - data->state.url)); + CURL_TRC_CF(data, cf, "[%s] resume sending", data->state.url); Curl_expire(data, 0, EXPIRE_RUN_NOW); } } @@ -277,7 +275,7 @@ static CURLcode h3_data_setup(struct Curl_cfilter *cf, stream->id = -1; Curl_bufq_initp(&stream->recvbuf, &ctx->stream_bufcp, 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; } @@ -288,8 +286,7 @@ static void h3_data_done(struct Curl_cfilter *cf, struct Curl_easy *data) (void)cf; if(stream) { - DEBUGF(LOG_CF(data, cf, "[h3sid=%"PRId64"] easy handle is done", - stream->id)); + CURL_TRC_CF(data, cf, "[h3sid=%"PRId64"] easy handle is done", stream->id); if(stream_send_is_suspended(data)) { data->req.keepon &= ~KEEP_SEND_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); } if(result) { - DEBUGF(LOG_CF(x->data, x->cf, - "[h3sid=%"PRId64"][HEADERS][%.*s: %.*s] error %d", - stream? stream->id : -1, (int)name_len, name, - (int)value_len, value, result)); + CURL_TRC_CF(x->data, x->cf, + "[h3sid=%"PRId64"][HEADERS][%.*s: %.*s] error %d", + stream? stream->id : -1, (int)name_len, name, + (int)value_len, value, result); } return result; } @@ -455,8 +452,8 @@ static CURLcode cf_recv_body(struct Curl_cfilter *cf, stream_resp_read, &cb_ctx, &result); if(nwritten < 0 && result != CURLE_AGAIN) { - DEBUGF(LOG_CF(data, cf, "[h3sid=%"PRId64"] recv_body error %zd", - stream->id, nwritten)); + CURL_TRC_CF(data, cf, "[h3sid=%"PRId64"] recv_body error %zd", + stream->id, nwritten); failf(data, "Error %d in HTTP/3 response body for stream[%"PRId64"]", result, stream->id); stream->closed = TRUE; @@ -514,7 +511,7 @@ static CURLcode h3_process_event(struct Curl_cfilter *cf, rc, stream3_id); 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; case QUICHE_H3_EVENT_DATA: @@ -524,7 +521,7 @@ static CURLcode h3_process_event(struct Curl_cfilter *cf, break; 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->reset = TRUE; stream->send_closed = TRUE; @@ -532,7 +529,7 @@ static CURLcode h3_process_event(struct Curl_cfilter *cf, break; 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) { result = write_resp_raw(cf, data, "\r\n", 2); if(result) @@ -544,12 +541,12 @@ static CURLcode h3_process_event(struct Curl_cfilter *cf, break; 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; default: - DEBUGF(LOG_CF(data, cf, "[h3sid=%"PRId64"] recv, unhandled event %d", - stream3_id, quiche_h3_event_type(ev))); + CURL_TRC_CF(data, cf, "[h3sid=%"PRId64"] recv, unhandled event %d", + stream3_id, quiche_h3_event_type(ev)); break; } return result; @@ -571,26 +568,25 @@ static CURLcode cf_poll_events(struct Curl_cfilter *cf, break; } else if(stream3_id < 0) { - DEBUGF(LOG_CF(data, cf, "[h3sid=%"PRId64"] error poll: %"PRId64, - stream? stream->id : -1, stream3_id)); + CURL_TRC_CF(data, cf, "[h3sid=%"PRId64"] error poll: %"PRId64, + stream? stream->id : -1, stream3_id); return CURLE_HTTP3; } sdata = get_stream_easy(cf, data, stream3_id); if(!sdata) { - DEBUGF(LOG_CF(data, cf, "[h3sid=%"PRId64"] discard event %s for " - "unknown [h3sid=%"PRId64"]", - stream? stream->id : -1, cf_ev_name(ev), - stream3_id)); + CURL_TRC_CF(data, cf, "[h3sid=%"PRId64"] discard event %s for " + "unknown [h3sid=%"PRId64"]", + stream? stream->id : -1, cf_ev_name(ev), stream3_id); } else { result = h3_process_event(cf, sdata, stream3_id, ev); drain_stream(cf, sdata); if(result) { - DEBUGF(LOG_CF(data, cf, "[h3sid=%"PRId64"] error processing event %s " - "for [h3sid=%"PRId64"] -> %d", - stream? stream->id : -1, cf_ev_name(ev), - stream3_id, result)); + CURL_TRC_CF(data, cf, "[h3sid=%"PRId64"] error processing event %s " + "for [h3sid=%"PRId64"] -> %d", + stream? stream->id : -1, cf_ev_name(ev), + stream3_id, result); if(data == sdata) { /* Only report this error to the caller if it is about the * 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); if(nread < 0) { 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; } 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) { - DEBUGF(LOG_CF(r->data, r->cf, "ingress, quiche only read %zd/%zu bytes", - nread, pktlen)); + CURL_TRC_CF(r->data, r->cf, "ingress, quiche only read %zd/%zu bytes", + nread, pktlen); } 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 */ nread = Curl_bufq_sipn(&ctx->q.sendbuf, 0, 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(result != CURLE_AGAIN) return result; @@ -795,8 +788,8 @@ static ssize_t recv_closed_stream(struct Curl_cfilter *cf, failf(data, "HTTP/3 stream %" PRId64 " reset by server", stream->id); *err = stream->resp_got_header? CURLE_PARTIAL_FILE : CURLE_RECV_ERROR; - DEBUGF(LOG_CF(data, cf, "[h3sid=%" PRId64 "] cf_recv, was reset -> %d", - stream->id, *err)); + CURL_TRC_CF(data, cf, "[h3sid=%" PRId64 "] cf_recv, was reset -> %d", + stream->id, *err); } else if(!stream->resp_got_header) { failf(data, @@ -805,14 +798,14 @@ static ssize_t recv_closed_stream(struct Curl_cfilter *cf, stream->id); /* *err = CURLE_PARTIAL_FILE; */ *err = CURLE_RECV_ERROR; - DEBUGF(LOG_CF(data, cf, "[h3sid=%" PRId64 "] cf_recv, closed incomplete" - " -> %d", stream->id, *err)); + CURL_TRC_CF(data, cf, "[h3sid=%" PRId64 "] cf_recv, closed incomplete" + " -> %d", stream->id, *err); } else { *err = CURLE_OK; nread = 0; - DEBUGF(LOG_CF(data, cf, "[h3sid=%" PRId64 "] cf_recv, closed ok" - " -> %d", stream->id, *err)); + CURL_TRC_CF(data, cf, "[h3sid=%" PRId64 "] cf_recv, closed ok" + " -> %d", stream->id, *err); } 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)) { nread = Curl_bufq_read(&stream->recvbuf, (unsigned char *)buf, len, err); - DEBUGF(LOG_CF(data, cf, "[h3sid=%" PRId64 "] read recvbuf(len=%zu) " - "-> %zd, %d", stream->id, len, nread, *err)); + CURL_TRC_CF(data, cf, "[h3sid=%" PRId64 "] read recvbuf(len=%zu) " + "-> %zd, %d", stream->id, len, nread, *err); if(nread < 0) goto out; } 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; nread = -1; 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)) { nread = Curl_bufq_read(&stream->recvbuf, (unsigned char *)buf, len, err); - DEBUGF(LOG_CF(data, cf, "[h3sid=%" PRId64 "] read recvbuf(len=%zu) " - "-> %zd, %d", stream->id, len, nread, *err)); + CURL_TRC_CF(data, cf, "[h3sid=%" PRId64 "] read recvbuf(len=%zu) " + "-> %zd, %d", stream->id, len, nread, *err); if(nread < 0) goto out; } @@ -878,16 +871,16 @@ static ssize_t cf_quiche_recv(struct Curl_cfilter *cf, struct Curl_easy *data, out: result = cf_flush_egress(cf, data); if(result) { - DEBUGF(LOG_CF(data, cf, "cf_recv, flush egress failed")); + CURL_TRC_CF(data, cf, "cf_recv, flush egress failed"); *err = result; nread = -1; } if(nread > 0) ctx->data_recvd += nread; - DEBUGF(LOG_CF(data, cf, "[h3sid=%"PRId64"] cf_recv(total=%" - CURL_FORMAT_CURL_OFF_T ") -> %zd, %d", - stream ? stream->id : (int64_t)0, - ctx->data_recvd, nread, *err)); + CURL_TRC_CF(data, cf, "[h3sid=%"PRId64"] cf_recv(total=%" + CURL_FORMAT_CURL_OFF_T ") -> %zd, %d", + stream ? stream->id : (int64_t)0, + ctx->data_recvd, nread, *err); return nread; } @@ -975,16 +968,16 @@ static ssize_t h3_open_stream(struct Curl_cfilter *cf, if(QUICHE_H3_ERR_STREAM_BLOCKED == stream3_id) { /* quiche seems to report this error if the connection window is * exhausted. Which happens frequently and intermittent. */ - DEBUGF(LOG_CF(data, cf, "send_request(%s) rejected with BLOCKED", - data->state.url)); + CURL_TRC_CF(data, cf, "send_request(%s) rejected with BLOCKED", + data->state.url); stream_send_suspend(cf, data); *err = CURLE_AGAIN; nwritten = -1; goto out; } else { - DEBUGF(LOG_CF(data, cf, "send_request(%s) -> %" PRId64, - data->state.url, stream3_id)); + CURL_TRC_CF(data, cf, "send_request(%s) -> %" PRId64, + data->state.url, stream3_id); } *err = CURLE_SEND_ERROR; nwritten = -1; @@ -998,8 +991,8 @@ static ssize_t h3_open_stream(struct Curl_cfilter *cf, stream->reset = FALSE; infof(data, "Using HTTP/3 Stream ID: %" PRId64, stream3_id); - DEBUGF(LOG_CF(data, cf, "[h3sid=%" PRId64 "] opened for %s", - stream3_id, data->state.url)); + CURL_TRC_CF(data, cf, "[h3sid=%" PRId64 "] opened for %s", + stream3_id, data->state.url); out: 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 * sending. But when do we open again? */ if(!quiche_conn_stream_writable(ctx->qconn, stream->id, len)) { - DEBUGF(LOG_CF(data, cf, "[h3sid=%" PRId64 "] send_body(len=%zu) " - "-> window exhausted", stream->id, len)); + CURL_TRC_CF(data, cf, "[h3sid=%" PRId64 "] send_body(len=%zu) " + "-> window exhausted", stream->id, len); stream_send_suspend(cf, data); } *err = CURLE_AGAIN; @@ -1046,15 +1039,15 @@ static ssize_t cf_quiche_send(struct Curl_cfilter *cf, struct Curl_easy *data, goto out; } else if(nwritten == QUICHE_H3_TRANSPORT_ERR_FINAL_SIZE) { - DEBUGF(LOG_CF(data, cf, "[h3sid=%" PRId64 "] send_body(len=%zu) " - "-> exceeds size", stream->id, len)); + CURL_TRC_CF(data, cf, "[h3sid=%" PRId64 "] send_body(len=%zu) " + "-> exceeds size", stream->id, len); *err = CURLE_SEND_ERROR; nwritten = -1; goto out; } else if(nwritten < 0) { - DEBUGF(LOG_CF(data, cf, "[h3sid=%" PRId64 "] send_body(len=%zu) " - "-> quiche err %zd", stream->id, len, nwritten)); + CURL_TRC_CF(data, cf, "[h3sid=%" PRId64 "] send_body(len=%zu) " + "-> quiche err %zd", stream->id, len, nwritten); *err = CURLE_SEND_ERROR; nwritten = -1; 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) stream->send_closed = TRUE; - DEBUGF(LOG_CF(data, cf, "[h3sid=%" PRId64 "] send body(len=%zu, " - "left=%" CURL_FORMAT_CURL_OFF_T ") -> %zd", - stream->id, len, stream->upload_left, nwritten)); + CURL_TRC_CF(data, cf, "[h3sid=%" PRId64 "] send body(len=%zu, " + "left=%" CURL_FORMAT_CURL_OFF_T ") -> %zd", + stream->id, len, stream->upload_left, nwritten); *err = CURLE_OK; } } @@ -1081,8 +1074,8 @@ out: *err = result; nwritten = -1; } - DEBUGF(LOG_CF(data, cf, "[h3sid=%" PRId64 "] cf_send(len=%zu) -> %zd, %d", - stream? stream->id : -1, len, nwritten, *err)); + CURL_TRC_CF(data, cf, "[h3sid=%" PRId64 "] cf_send(len=%zu) -> %zd, %d", + stream? stream->id : -1, len, nwritten, *err); return nwritten; } @@ -1171,15 +1164,15 @@ static CURLcode cf_quiche_data_event(struct Curl_cfilter *cf, stream->upload_left = 0; body[0] = 'X'; sent = cf_quiche_send(cf, data, body, 0, &result); - DEBUGF(LOG_CF(data, cf, "[h3sid=%"PRId64"] DONE_SEND -> %zd, %d", - stream->id, sent, result)); + CURL_TRC_CF(data, cf, "[h3sid=%"PRId64"] DONE_SEND -> %zd, %d", + stream->id, sent, result); } break; } case CF_CTRL_DATA_IDLE: result = cf_flush_egress(cf, data); 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; default: break; @@ -1210,7 +1203,7 @@ static CURLcode cf_verify_peer(struct Curl_cfilter *cf, goto out; } else - DEBUGF(LOG_CF(data, cf, "Skipped certificate verification")); + CURL_TRC_CF(data, cf, "Skipped certificate verification"); ctx->h3config = quiche_h3_config_new(); if(!ctx->h3config) { @@ -1357,8 +1350,8 @@ static CURLcode cf_connect_start(struct Curl_cfilter *cf, offset += 1 + alpn_len; } - DEBUGF(LOG_CF(data, cf, "Sent QUIC client Initial, ALPN: %s", - alpn_protocols + 1)); + CURL_TRC_CF(data, cf, "Sent QUIC client Initial, ALPN: %s", + alpn_protocols + 1); } 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) { /* 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; } @@ -1412,12 +1405,12 @@ static CURLcode cf_quiche_connect(struct Curl_cfilter *cf, goto out; if(quiche_conn_is_established(ctx->qconn)) { - DEBUGF(LOG_CF(data, cf, "handshake complete after %dms", - (int)Curl_timediff(now, ctx->started_at))); + CURL_TRC_CF(data, cf, "handshake complete after %dms", + (int)Curl_timediff(now, ctx->started_at)); ctx->handshake_at = now; result = cf_verify_peer(cf, data); if(!result) { - DEBUGF(LOG_CF(data, cf, "peer verified")); + CURL_TRC_CF(data, cf, "peer verified"); cf->connected = TRUE; cf->conn->alpn = CURL_HTTP_VERSION_3; *done = TRUE; @@ -1436,8 +1429,8 @@ static CURLcode cf_quiche_connect(struct Curl_cfilter *cf, */ int reconn_delay_ms = 200; - DEBUGF(LOG_CF(data, cf, "connect, remote closed, reconnect after %dms", - reconn_delay_ms)); + CURL_TRC_CF(data, cf, "connect, remote closed, reconnect after %dms", + reconn_delay_ms); Curl_conn_cf_close(cf->next, data); cf_quiche_ctx_clear(ctx); 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); } *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; } case CF_QUERY_CONNECT_REPLY_MS: diff --git a/lib/vquic/vquic.c b/lib/vquic/vquic.c index 399de0b2ca..9b296d0745 100644 --- a/lib/vquic/vquic.c +++ b/lib/vquic/vquic.c @@ -43,7 +43,7 @@ #include "bufq.h" #include "dynbuf.h" #include "cfilters.h" -#include "curl_log.h" +#include "curl_trc.h" #include "curl_msh3.h" #include "curl_ngtcp2.h" #include "curl_quiche.h" @@ -253,11 +253,9 @@ CURLcode vquic_flush(struct Curl_cfilter *cf, struct Curl_easy *data, 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); - DEBUGF(LOG_CF(data, cf, "vquic_send(len=%zu, gso=%zu) -> %d, sent=%zu", - blen, gsolen, result, sent)); + CURL_TRC_CF(data, cf, "vquic_send(len=%zu, gso=%zu) -> %d, sent=%zu", + blen, gsolen, result, sent); if(result) { if(result == CURLE_AGAIN) { 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_gsolen = gsolen; qctx->gsolen = tail_gsolen; - DEBUGF(LOG_CF(data, cf, "vquic_send_tail_split: [%zu gso=%zu][%zu gso=%zu]", - qctx->split_len, qctx->split_gsolen, - tail_len, qctx->gsolen)); + CURL_TRC_CF(data, cf, "vquic_send_tail_split: [%zu gso=%zu][%zu gso=%zu]", + qctx->split_len, qctx->split_gsolen, + tail_len, qctx->gsolen); return vquic_flush(cf, data, qctx); } @@ -330,7 +328,7 @@ static CURLcode recvmmsg_packets(struct Curl_cfilter *cf, ; if(mcount == -1) { if(SOCKERRNO == EAGAIN || SOCKERRNO == EWOULDBLOCK) { - DEBUGF(LOG_CF(data, cf, "ingress, recvmmsg -> EAGAIN")); + CURL_TRC_CF(data, cf, "ingress, recvmmsg -> EAGAIN"); goto out; } if(!cf->connected && SOCKERRNO == ECONNREFUSED) { @@ -349,7 +347,7 @@ static CURLcode recvmmsg_packets(struct Curl_cfilter *cf, goto out; } - DEBUGF(LOG_CF(data, cf, "recvmmsg() -> %d packets", mcount)); + CURL_TRC_CF(data, cf, "recvmmsg() -> %d packets", mcount); pkts += mcount; for(i = 0; i < mcount; ++i) { total_nread += mmsg[i].msg_len; @@ -362,8 +360,8 @@ static CURLcode recvmmsg_packets(struct Curl_cfilter *cf, } out: - DEBUGF(LOG_CF(data, cf, "recvd %zu packets with %zu bytes -> %d", - pkts, total_nread, result)); + CURL_TRC_CF(data, cf, "recvd %zu packets with %zu bytes -> %d", + pkts, total_nread, result); return result; } @@ -425,8 +423,8 @@ static CURLcode recvmsg_packets(struct Curl_cfilter *cf, } out: - DEBUGF(LOG_CF(data, cf, "recvd %zu packets with %zu bytes -> %d", - pkts, total_nread, result)); + CURL_TRC_CF(data, cf, "recvd %zu packets with %zu bytes -> %d", + pkts, total_nread, result); return result; } @@ -454,7 +452,7 @@ static CURLcode recvfrom_packets(struct Curl_cfilter *cf, ; if(nread == -1) { if(SOCKERRNO == EAGAIN || SOCKERRNO == EWOULDBLOCK) { - DEBUGF(LOG_CF(data, cf, "ingress, recvfrom -> EAGAIN")); + CURL_TRC_CF(data, cf, "ingress, recvfrom -> EAGAIN"); goto out; } if(!cf->connected && SOCKERRNO == ECONNREFUSED) { @@ -482,8 +480,8 @@ static CURLcode recvfrom_packets(struct Curl_cfilter *cf, } out: - DEBUGF(LOG_CF(data, cf, "recvd %zu packets with %zu bytes -> %d", - pkts, total_nread, result)); + CURL_TRC_CF(data, cf, "recvd %zu packets with %zu bytes -> %d", + pkts, total_nread, result); return result; } #endif /* !HAVE_SENDMMSG && !HAVE_SENDMSG */ diff --git a/lib/vssh/libssh2.c b/lib/vssh/libssh2.c index b3d07bf6ef..0dd7eba91a 100644 --- a/lib/vssh/libssh2.c +++ b/lib/vssh/libssh2.c @@ -2534,7 +2534,8 @@ static CURLcode ssh_statemach_act(struct Curl_easy *data, bool *block) if(from > size) { failf(data, "Offset (%" 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; } if(from > to) { @@ -2560,7 +2561,7 @@ static CURLcode ssh_statemach_act(struct Curl_easy *data, bool *block) failf(data, "Offset (%" 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; } /* 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) { failf(data, "Offset (%" 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; } } diff --git a/lib/vtls/mbedtls.c b/lib/vtls/mbedtls.c index 8d0fa39c0e..81592576a0 100644 --- a/lib/vtls/mbedtls.c +++ b/lib/vtls/mbedtls.c @@ -165,8 +165,8 @@ static int bio_cf_write(void *bio, const unsigned char *buf, size_t blen) DEBUGASSERT(data); 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", - blen, nwritten, result)); + CURL_TRC_CF(data, cf, "bio_cf_out_write(len=%zu) -> %zd, err=%d", + blen, nwritten, result); if(nwritten < 0 && CURLE_AGAIN == result) { 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; 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", - blen, nread, result)); + CURL_TRC_CF(data, cf, "bio_cf_in_read(len=%zu) -> %zd, err=%d", + blen, nread, result); if(nread < 0 && CURLE_AGAIN == result) { nread = MBEDTLS_ERR_SSL_WANT_READ; } diff --git a/lib/vtls/openssl.c b/lib/vtls/openssl.c index c458f33692..36d841f35e 100644 --- a/lib/vtls/openssl.c +++ b/lib/vtls/openssl.c @@ -722,8 +722,8 @@ static int bio_cf_out_write(BIO *bio, const char *buf, int blen) DEBUGASSERT(data); 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", - blen, (int)nwritten, result)); + CURL_TRC_CF(data, cf, "bio_cf_out_write(len=%d) -> %d, err=%d", + blen, (int)nwritten, result); BIO_clear_retry_flags(bio); backend->io_result = result; if(nwritten < 0) { @@ -749,8 +749,8 @@ static int bio_cf_in_read(BIO *bio, char *buf, int blen) return 0; 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", - blen, (int)nread, result)); + CURL_TRC_CF(data, cf, "bio_cf_in_read(len=%d) -> %d, err=%d", + blen, (int)nread, result); BIO_clear_retry_flags(bio); backend->io_result = result; if(nread < 0) { diff --git a/lib/vtls/rustls.c b/lib/vtls/rustls.c index 76d3e24d23..a3e9d964c9 100644 --- a/lib/vtls/rustls.c +++ b/lib/vtls/rustls.c @@ -104,10 +104,6 @@ read_cb(void *userdata, uint8_t *buf, uintptr_t len, uintptr_t *out_n) ret = EINVAL; } *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; } @@ -128,7 +124,7 @@ write_cb(void *userdata, const uint8_t *buf, uintptr_t len, uintptr_t *out_n) } *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)); */ return ret; @@ -267,8 +263,8 @@ cr_recv(struct Curl_cfilter *cf, struct Curl_easy *data, } out: - DEBUGF(LOG_CF(data, cf, "cf_recv(len=%zu) -> %zd, %d", - plainlen, nread, *err)); + CURL_TRC_CF(data, cf, "cf_recv(len=%zu) -> %zd, %d", + plainlen, nread, *err); return nread; } @@ -302,7 +298,7 @@ cr_send(struct Curl_cfilter *cf, struct Curl_easy *data, DEBUGASSERT(backend); 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.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, &tlswritten); if(io_error == EAGAIN || io_error == EWOULDBLOCK) { - DEBUGF(LOG_CF(data, cf, "cf_send: EAGAIN after %zu bytes", - tlswritten_total)); + CURL_TRC_CF(data, cf, "cf_send: EAGAIN after %zu bytes", + tlswritten_total); *err = CURLE_AGAIN; return -1; } @@ -344,7 +340,7 @@ cr_send(struct Curl_cfilter *cf, struct Curl_easy *data, *err = CURLE_WRITE_ERROR; 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; } diff --git a/lib/vtls/sectransp.c b/lib/vtls/sectransp.c index 0459ac0655..e458efb18f 100644 --- a/lib/vtls/sectransp.c +++ b/lib/vtls/sectransp.c @@ -845,8 +845,8 @@ static OSStatus bio_cf_in_read(SSLConnectionRef connection, DEBUGASSERT(data); nread = Curl_conn_cf_recv(cf->next, data, buf, *dataLength, &result); - DEBUGF(LOG_CF(data, cf, "bio_read(len=%zu) -> %zd, result=%d", - *dataLength, nread, result)); + CURL_TRC_CF(data, cf, "bio_read(len=%zu) -> %zd, result=%d", + *dataLength, nread, result); if(nread < 0) { switch(result) { case CURLE_OK: @@ -885,8 +885,8 @@ static OSStatus bio_cf_out_write(SSLConnectionRef connection, DEBUGASSERT(data); nwritten = Curl_conn_cf_send(cf->next, data, buf, *dataLength, &result); - DEBUGF(LOG_CF(data, cf, "bio_send(len=%zu) -> %zd, result=%d", - *dataLength, nwritten, result)); + CURL_TRC_CF(data, cf, "bio_send(len=%zu) -> %zd, result=%d", + *dataLength, nwritten, result); if(nwritten <= 0) { if(result == CURLE_AGAIN) { 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 understood by humans. */ 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, cipher_start - ciphers, cipher_end - ciphers); @@ -1663,7 +1663,7 @@ static CURLcode sectransp_connect_step1(struct Curl_cfilter *cf, DEBUGASSERT(backend); - DEBUGF(LOG_CF(data, cf, "connect_step1")); + CURL_TRC_CF(data, cf, "connect_step1"); GetDarwinVersionNumber(&darwinver_maj, &darwinver_min); #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. */ rc = append_cert_to_array(data, certbuf, buflen, array); 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; goto out; } @@ -2308,7 +2308,7 @@ static CURLcode verify_cert_buf(struct Curl_cfilter *cf, rc = append_cert_to_array(data, der, derlen, array); free(der); 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; goto out; } @@ -2324,7 +2324,7 @@ static CURLcode verify_cert_buf(struct Curl_cfilter *cf, 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); if(ret != noErr) { failf(data, "SecTrustSetAnchorCertificates() returned error %d", ret); @@ -2346,11 +2346,11 @@ static CURLcode verify_cert_buf(struct Curl_cfilter *cf, switch(trust_eval) { case kSecTrustResultUnspecified: /* what does this really mean? */ - DEBUGF(LOG_CF(data, cf, "trust result: Unspecified")); + CURL_TRC_CF(data, cf, "trust result: Unspecified"); result = CURLE_OK; goto out; case kSecTrustResultProceed: - DEBUGF(LOG_CF(data, cf, "trust result: Proceed")); + CURL_TRC_CF(data, cf, "trust result: Proceed"); result = CURLE_OK; goto out; @@ -2383,7 +2383,7 @@ static CURLcode verify_cert(struct Curl_cfilter *cf, size_t buflen; 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); if(!certbuf) { return CURLE_OUT_OF_MEMORY; @@ -2393,7 +2393,7 @@ static CURLcode verify_cert(struct Curl_cfilter *cf, certbuf[ca_info_blob->len]='\0'; } 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) { failf(data, "SSL: failed to read or invalid CA certificate"); return CURLE_SSL_CACERT_BADFILE; @@ -2485,7 +2485,7 @@ static CURLcode pkp_pin_peer_pubkey(struct Curl_easy *data, spkiHeaderLength = 23; break; default: - infof(data, "SSL: unhandled public key length: %d", pubkeylen); + infof(data, "SSL: unhandled public key length: %zu", pubkeylen); #elif SECTRANSP_PINNEDPUBKEY_V2 default: /* 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_writing == connssl->connecting_state); DEBUGASSERT(backend); - DEBUGF(LOG_CF(data, cf, "connect_step2")); + CURL_TRC_CF(data, cf, "connect_step2"); /* Here goes nothing: */ check_handshake: @@ -3001,7 +3001,7 @@ static CURLcode sectransp_connect_step3(struct Curl_cfilter *cf, struct ssl_connect_data *connssl = cf->ctx; CURLcode result; - DEBUGF(LOG_CF(data, cf, "connect_step3")); + CURL_TRC_CF(data, cf, "connect_step3"); /* There is no step 3! * Well, okay, let's collect server certificates, and if verbose mode is on, * 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) { - DEBUGF(LOG_CF(data, cf, "connected")); + CURL_TRC_CF(data, cf, "connected"); connssl->state = ssl_connection_complete; *done = TRUE; } @@ -3157,7 +3157,7 @@ static void sectransp_close(struct Curl_cfilter *cf, struct Curl_easy *data) DEBUGASSERT(backend); if(backend->ssl_ctx) { - DEBUGF(LOG_CF(data, cf, "close")); + CURL_TRC_CF(data, cf, "close"); (void)SSLClose(backend->ssl_ctx); #if CURL_BUILD_MAC_10_8 || CURL_BUILD_IOS if(SSLCreateContext) @@ -3203,7 +3203,7 @@ static int sectransp_shutdown(struct Curl_cfilter *cf, what = SOCKET_READABLE(Curl_conn_cf_get_socket(cf, data), SSL_SHUTDOWN_TIMEOUT); - DEBUGF(LOG_CF(data, cf, "shutdown")); + CURL_TRC_CF(data, cf, "shutdown"); while(loop--) { if(what < 0) { /* anything that gets here is fatally bad */ @@ -3265,7 +3265,7 @@ static bool sectransp_data_pending(struct Curl_cfilter *cf, DEBUGASSERT(backend); 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); if(err == noErr) return buffer > 0UL; diff --git a/lib/vtls/vtls.c b/lib/vtls/vtls.c index 93568905fd..404f71a178 100644 --- a/lib/vtls/vtls.c +++ b/lib/vtls/vtls.c @@ -1596,7 +1596,7 @@ static ssize_t ssl_cf_recv(struct Curl_cfilter *cf, /* eof */ *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); 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 = { "SSL", CF_TYPE_SSL, - CURL_LOG_DEFAULT, + CURL_LOG_LVL_NONE, ssl_cf_destroy, ssl_cf_connect, ssl_cf_close, @@ -1715,7 +1715,7 @@ struct Curl_cftype Curl_cft_ssl = { struct Curl_cftype Curl_cft_ssl_proxy = { "SSL-PROXY", CF_TYPE_SSL, - CURL_LOG_DEFAULT, + CURL_LOG_LVL_NONE, ssl_cf_destroy, ssl_cf_connect, ssl_cf_close, diff --git a/lib/vtls/wolfssl.c b/lib/vtls/wolfssl.c index 623ec772c8..f6616257a5 100644 --- a/lib/vtls/wolfssl.c +++ b/lib/vtls/wolfssl.c @@ -290,8 +290,8 @@ static int bio_cf_out_write(WOLFSSL_BIO *bio, const char *buf, int blen) DEBUGASSERT(data); nwritten = Curl_conn_cf_send(cf->next, data, buf, blen, &result); backend->io_result = result; - DEBUGF(LOG_CF(data, cf, "bio_write(len=%d) -> %zd, %d", - blen, nwritten, result)); + CURL_TRC_CF(data, cf, "bio_write(len=%d) -> %zd, %d", + blen, nwritten, result); wolfSSL_BIO_clear_retry_flags(bio); if(nwritten < 0 && CURLE_AGAIN == result) 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); backend->io_result = result; - DEBUGF(LOG_CF(data, cf, "bio_read(len=%d) -> %zd, %d", - blen, nread, result)); + CURL_TRC_CF(data, cf, "bio_read(len=%d) -> %zd, %d", blen, nread, result); wolfSSL_BIO_clear_retry_flags(bio); if(nread < 0 && CURLE_AGAIN == result) 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_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; return -1; default: 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; return -1; } - DEBUGF(LOG_CF(data, cf, "wolfssl_send(len=%zu) -> %d, %d", - len, rc, err)); + CURL_TRC_CF(data, cf, "wolfssl_send(len=%zu) -> %d, %d", len, rc, err); failf(data, "SSL write: %s, errno %d", ERR_error_string(err, error_buffer), SOCKERRNO); @@ -1036,7 +1034,7 @@ static ssize_t wolfssl_send(struct Curl_cfilter *cf, 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; } @@ -1089,7 +1087,7 @@ static ssize_t wolfssl_recv(struct Curl_cfilter *cf, switch(err) { 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; return 0; case SSL_ERROR_NONE: @@ -1098,12 +1096,12 @@ static ssize_t wolfssl_recv(struct Curl_cfilter *cf, /* FALLTHROUGH */ case SSL_ERROR_WANT_WRITE: /* 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; return -1; default: 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; return -1; } @@ -1113,7 +1111,7 @@ static ssize_t wolfssl_recv(struct Curl_cfilter *cf, 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; } diff --git a/libcurl.def b/libcurl.def index e84d4c6558..1de609e80d 100644 --- a/libcurl.def +++ b/libcurl.def @@ -29,6 +29,7 @@ curl_global_cleanup curl_global_init curl_global_init_mem curl_global_sslset +curl_global_trace curl_maprintf curl_mfprintf curl_mime_addpart diff --git a/src/tool_getparam.c b/src/tool_getparam.c index bf81fb8c7c..fb27fffd1f 100644 --- a/src/tool_getparam.c +++ b/src/tool_getparam.c @@ -209,6 +209,7 @@ static const struct LongShort aliases[]= { {"$~", "happy-eyeballs-timeout-ms", ARG_STRING}, {"$!", "retry-all-errors", ARG_BOOL}, {"$%", "trace-ids", ARG_BOOL}, + {"$&", "trace-config", ARG_STRING}, {"0", "http1.0", ARG_NONE}, {"01", "http1.1", ARG_NONE}, {"02", "http2", ARG_NONE}, @@ -681,6 +682,61 @@ static void sethttpver(struct GlobalConfig *global, 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 */ char *nextarg, /* NULL if unset */ argv_item_t cleararg, @@ -1463,6 +1519,11 @@ ParameterError getparameter(const char *flag, /* f or -long-flag */ case '%': /* --trace-ids */ global->traceids = toggle; break; + case '&': /* --trace-config */ + if(set_trace_config(global, nextarg)) { + err = PARAM_NO_MEM; + } + break; } break; case '#': diff --git a/src/tool_listhelp.c b/src/tool_listhelp.c index f541c22b35..fe35e4429b 100644 --- a/src/tool_listhelp.c +++ b/src/tool_listhelp.c @@ -759,6 +759,9 @@ const struct helptxt helptext[] = { {" --trace-ascii ", "Like --trace, but without hex output", CURLHELP_VERBOSE}, + {" --trace-config", + "Configure which details to log in trace/verbose output", + CURLHELP_VERBOSE}, {" --trace-ids", "Add transfer and connection identifiers to trace/verbose output", CURLHELP_VERBOSE}, diff --git a/tests/data/test1135 b/tests/data/test1135 index 2239e0b436..0f055e9bc1 100644 --- a/tests/data/test1135 +++ b/tests/data/test1135 @@ -55,6 +55,7 @@ curl_free curl_global_init curl_global_init_mem curl_global_cleanup +curl_global_trace curl_global_sslset curl_slist_append curl_slist_free_all diff --git a/tests/http/test_15_tracing.py b/tests/http/test_15_tracing.py new file mode 100644 index 0000000000..dd2484ea47 --- /dev/null +++ b/tests/http/test_15_tracing.py @@ -0,0 +1,112 @@ +#!/usr/bin/env python3 +# -*- coding: utf-8 -*- +#*************************************************************************** +# _ _ ____ _ +# Project ___| | | | _ \| | +# / __| | | | |_) | | +# | (__| |_| | _ <| |___ +# \___|\___/|_| \_\_____| +# +# Copyright (C) Daniel Stenberg, , 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}' \ No newline at end of file diff --git a/tests/http/testenv/curl.py b/tests/http/testenv/curl.py index 54622b5d85..aee0779f72 100644 --- a/tests/http/testenv/curl.py +++ b/tests/http/testenv/curl.py @@ -337,8 +337,10 @@ class CurlClient: xargs.append('--proxytunnel') return xargs - def http_get(self, url: str, extra_args: Optional[List[str]] = None): - return self._raw(url, options=extra_args, with_stats=False) + def http_get(self, url: str, extra_args: Optional[List[str]] = None, + 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], alpn_proto: Optional[str] = None, @@ -463,11 +465,13 @@ class CurlClient: force_resolve=True, with_stats=False, with_headers=True, - with_trace=False): + with_trace=False, + def_tracing=True): args = self._complete_args( urls=urls, timeout=timeout, options=options, insecure=insecure, 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) if r.exit_code == 0 and with_headers: self._parse_headerfile(self._headerfile, r=r) @@ -479,15 +483,20 @@ class CurlClient: insecure=False, force_resolve=True, alpn_proto: Optional[str] = None, with_headers: bool = True, - with_trace: bool = False): + with_trace: bool = False, + def_tracing: bool = True): if not isinstance(urls, list): 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: args.extend(["-D", self._headerfile]) if with_trace or self.env.verbose > 2: args.extend(['--trace', self._tracefile]) + elif def_tracing is False: + pass elif self.env.verbose > 1: args.extend(['--trace-ascii', self._tracefile]) elif not self._silent: diff --git a/tests/unit/unit2600.c b/tests/unit/unit2600.c index 260ce6e1e7..b52db81a99 100644 --- a/tests/unit/unit2600.c +++ b/tests/unit/unit2600.c @@ -50,7 +50,7 @@ #include "urldata.h" #include "connect.h" #include "cfilters.h" -#include "curl_log.h" +#include "curl_trc.h" /* copied from hostip.c to switch using SIGALARM for timeouts. * 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 = { "TEST", CF_TYPE_IP_CONNECT, - CURL_LOG_DEFAULT, + CURL_LOG_LVL_NONE, cf_test_destroy, cf_test_connect, Curl_cf_def_close, diff --git a/tests/unit/unit2601.c b/tests/unit/unit2601.c index de2a9f9d66..c0c413be5e 100644 --- a/tests/unit/unit2601.c +++ b/tests/unit/unit2601.c @@ -25,7 +25,7 @@ #include "urldata.h" #include "bufq.h" -#include "curl_log.h" +#include "curl_trc.h" static CURLcode unit_setup(void) { diff --git a/tests/unit/unit2602.c b/tests/unit/unit2602.c index e596f8ad01..41476c60f0 100644 --- a/tests/unit/unit2602.c +++ b/tests/unit/unit2602.c @@ -26,7 +26,7 @@ #include "urldata.h" #include "dynbuf.h" #include "dynhds.h" -#include "curl_log.h" +#include "curl_trc.h" static CURLcode unit_setup(void) { diff --git a/tests/unit/unit2603.c b/tests/unit/unit2603.c index ddd90d1526..3c61776360 100644 --- a/tests/unit/unit2603.c +++ b/tests/unit/unit2603.c @@ -26,7 +26,7 @@ #include "urldata.h" #include "http.h" #include "http1.h" -#include "curl_log.h" +#include "curl_trc.h" static CURLcode unit_setup(void) { -- 2.47.3