curl/lib/curl_trc.c

Ignoring revisions in .git-blame-ignore-revs. Click here to bypass and see the normal blame view.

501 lines
13 KiB
C
Raw Normal View History

/***************************************************************************
* _ _ ____ _
* Project ___| | | | _ \| |
* / __| | | | |_) | |
* | (__| |_| | _ <| |___
* \___|\___/|_| \_\_____|
*
* Copyright (C) Daniel Stenberg, <daniel@haxx.se>, et al.
*
* This software is licensed as described in the file COPYING, which
* you should have received as part of this distribution. The terms
* are also available at https://curl.se/docs/copyright.html.
*
* You may opt to use, copy, modify, merge, publish, distribute and/or sell
* copies of the Software, and permit persons to whom the Software is
* furnished to do so, under the terms of the COPYING file.
*
* This software is distributed on an "AS IS" basis, WITHOUT WARRANTY OF ANY
* KIND, either express or implied.
*
* SPDX-License-Identifier: curl
*
***************************************************************************/
#include "curl_setup.h"
#include <curl/curl.h>
#include "curl_trc.h"
#include "urldata.h"
#include "easyif.h"
#include "cfilters.h"
#include "timeval.h"
#include "multiif.h"
#include "strcase.h"
#include "cf-socket.h"
#include "connect.h"
#include "doh.h"
#include "http2.h"
#include "http_proxy.h"
#include "cf-h1-proxy.h"
#include "cf-h2-proxy.h"
#include "cf-haproxy.h"
#include "cf-https-connect.h"
#include "socks.h"
#include "strtok.h"
#include "vtls/vtls.h"
#include "vquic/vquic.h"
/* The last 3 #include files should be in this order */
#include "curl_printf.h"
#include "curl_memory.h"
#include "memdebug.h"
#ifndef ARRAYSIZE
#define ARRAYSIZE(A) (sizeof(A)/sizeof((A)[0]))
#endif
void Curl_debug(struct Curl_easy *data, curl_infotype type,
char *ptr, size_t size)
{
if(data->set.verbose) {
static const char s_infotype[CURLINFO_END][3] = {
"* ", "< ", "> ", "{ ", "} ", "{ ", "} " };
if(data->set.fdebug) {
bool inCallback = Curl_is_in_callback(data);
Curl_set_in_callback(data, TRUE);
(void)(*data->set.fdebug)(data, type, ptr, size, data->set.debugdata);
Curl_set_in_callback(data, inCallback);
}
else {
switch(type) {
case CURLINFO_TEXT:
case CURLINFO_HEADER_OUT:
case CURLINFO_HEADER_IN:
fwrite(s_infotype[type], 2, 1, data->set.err);
fwrite(ptr, size, 1, data->set.err);
break;
default: /* nada */
break;
}
}
}
}
/* Curl_failf() is for messages stating why we failed.
* The message SHALL NOT include any LF or CR.
*/
void Curl_failf(struct Curl_easy *data, const char *fmt, ...)
{
DEBUGASSERT(!strchr(fmt, '\n'));
if(data->set.verbose || data->set.errorbuffer) {
va_list ap;
int len;
char error[CURL_ERROR_SIZE + 2];
va_start(ap, fmt);
len = mvsnprintf(error, CURL_ERROR_SIZE, fmt, ap);
if(data->set.errorbuffer && !data->state.errorbuf) {
strcpy(data->set.errorbuffer, error);
data->state.errorbuf = TRUE; /* wrote error string */
}
error[len++] = '\n';
error[len] = '\0';
Curl_debug(data, CURLINFO_TEXT, error, len);
va_end(ap);
}
}
#if !defined(CURL_DISABLE_VERBOSE_STRINGS)
/* Curl_infof() is for info message along the way */
#define MAXINFO 2048
static void trc_infof(struct Curl_easy *data, struct curl_trc_feat *feat,
const char * const fmt, va_list ap) CURL_PRINTF(3, 0);
static void trc_infof(struct Curl_easy *data, struct curl_trc_feat *feat,
const char * const fmt, va_list ap)
{
int len = 0;
char buffer[MAXINFO + 5];
if(feat)
len = msnprintf(buffer, (MAXINFO + 1), "[%s] ", feat->name);
len += mvsnprintf(buffer + len, (MAXINFO + 1) - len, fmt, ap);
if(len >= MAXINFO) { /* too long, shorten with '...' */
--len;
buffer[len++] = '.';
buffer[len++] = '.';
buffer[len++] = '.';
}
buffer[len++] = '\n';
buffer[len] = '\0';
Curl_debug(data, CURLINFO_TEXT, buffer, len);
}
void Curl_infof(struct Curl_easy *data, const char *fmt, ...)
{
DEBUGASSERT(!strchr(fmt, '\n'));
if(Curl_trc_is_verbose(data)) {
va_list ap;
va_start(ap, fmt);
trc_infof(data, data->state.feat, fmt, ap);
va_end(ap);
}
}
void Curl_trc_cf_infof(struct Curl_easy *data, struct Curl_cfilter *cf,
const char *fmt, ...)
{
DEBUGASSERT(cf);
if(Curl_trc_cf_is_verbose(cf, data)) {
va_list ap;
int len = 0;
char buffer[MAXINFO + 2];
if(data->state.feat)
len += msnprintf(buffer + len, MAXINFO - len, "[%s] ",
data->state.feat->name);
if(cf->sockindex)
len += msnprintf(buffer + len, MAXINFO - len, "[%s-%d] ",
cf->cft->name, cf->sockindex);
else
len += msnprintf(buffer + len, MAXINFO - len, "[%s] ", cf->cft->name);
va_start(ap, fmt);
len += mvsnprintf(buffer + len, MAXINFO - len, fmt, ap);
va_end(ap);
buffer[len++] = '\n';
buffer[len] = '\0';
Curl_debug(data, CURLINFO_TEXT, buffer, len);
}
}
struct curl_trc_feat Curl_trc_feat_read = {
"READ",
CURL_LOG_LVL_NONE,
};
struct curl_trc_feat Curl_trc_feat_write = {
"WRITE",
CURL_LOG_LVL_NONE,
};
void Curl_trc_read(struct Curl_easy *data, const char *fmt, ...)
{
DEBUGASSERT(!strchr(fmt, '\n'));
if(Curl_trc_ft_is_verbose(data, &Curl_trc_feat_read)) {
va_list ap;
va_start(ap, fmt);
trc_infof(data, &Curl_trc_feat_read, fmt, ap);
va_end(ap);
}
}
void Curl_trc_write(struct Curl_easy *data, const char *fmt, ...)
{
DEBUGASSERT(!strchr(fmt, '\n'));
if(Curl_trc_ft_is_verbose(data, &Curl_trc_feat_write)) {
va_list ap;
va_start(ap, fmt);
trc_infof(data, &Curl_trc_feat_write, fmt, ap);
va_end(ap);
}
}
#ifndef CURL_DISABLE_FTP
struct curl_trc_feat Curl_trc_feat_ftp = {
"FTP",
CURL_LOG_LVL_NONE,
};
void Curl_trc_ftp(struct Curl_easy *data, const char *fmt, ...)
{
DEBUGASSERT(!strchr(fmt, '\n'));
if(Curl_trc_ft_is_verbose(data, &Curl_trc_feat_ftp)) {
va_list ap;
va_start(ap, fmt);
trc_infof(data, &Curl_trc_feat_ftp, fmt, ap);
va_end(ap);
}
}
#endif /* !CURL_DISABLE_FTP */
#ifndef CURL_DISABLE_SMTP
struct curl_trc_feat Curl_trc_feat_smtp = {
"SMTP",
CURL_LOG_LVL_NONE,
};
void Curl_trc_smtp(struct Curl_easy *data, const char *fmt, ...)
{
DEBUGASSERT(!strchr(fmt, '\n'));
if(Curl_trc_ft_is_verbose(data, &Curl_trc_feat_smtp)) {
va_list ap;
va_start(ap, fmt);
trc_infof(data, &Curl_trc_feat_smtp, fmt, ap);
va_end(ap);
}
}
#endif /* !CURL_DISABLE_SMTP */
#ifdef USE_SSL
struct curl_trc_feat Curl_trc_feat_ssls = {
"SSLS",
CURL_LOG_LVL_NONE,
};
void Curl_trc_ssls(struct Curl_easy *data, const char *fmt, ...)
{
DEBUGASSERT(!strchr(fmt, '\n'));
if(Curl_trc_ft_is_verbose(data, &Curl_trc_feat_ssls)) {
va_list ap;
va_start(ap, fmt);
trc_infof(data, &Curl_trc_feat_ssls, fmt, ap);
va_end(ap);
}
}
#endif /* USE_SSL */
#if !defined(CURL_DISABLE_WEBSOCKETS) && !defined(CURL_DISABLE_HTTP)
struct curl_trc_feat Curl_trc_feat_ws = {
"WS",
CURL_LOG_LVL_NONE,
};
void Curl_trc_ws(struct Curl_easy *data, const char *fmt, ...)
{
DEBUGASSERT(!strchr(fmt, '\n'));
if(Curl_trc_ft_is_verbose(data, &Curl_trc_feat_ws)) {
va_list ap;
va_start(ap, fmt);
trc_infof(data, &Curl_trc_feat_ws, fmt, ap);
va_end(ap);
}
}
#endif /* !CURL_DISABLE_WEBSOCKETS && !CURL_DISABLE_HTTP */
#define TRC_CT_NONE (0)
#define TRC_CT_PROTOCOL (1<<(0))
#define TRC_CT_NETWORK (1<<(1))
#define TRC_CT_PROXY (1<<(2))
struct trc_feat_def {
struct curl_trc_feat *feat;
unsigned int category;
};
static struct trc_feat_def trc_feats[] = {
{ &Curl_trc_feat_read, TRC_CT_NONE },
{ &Curl_trc_feat_write, TRC_CT_NONE },
#ifndef CURL_DISABLE_FTP
{ &Curl_trc_feat_ftp, TRC_CT_PROTOCOL },
#endif
#ifndef CURL_DISABLE_DOH
{ &Curl_doh_trc, TRC_CT_NETWORK },
#endif
#ifndef CURL_DISABLE_SMTP
{ &Curl_trc_feat_smtp, TRC_CT_PROTOCOL },
#endif
#ifdef USE_SSL
{ &Curl_trc_feat_ssls, TRC_CT_NETWORK },
#endif
#if !defined(CURL_DISABLE_WEBSOCKETS) && !defined(CURL_DISABLE_HTTP)
{ &Curl_trc_feat_ws, TRC_CT_PROTOCOL },
#endif
};
struct trc_cft_def {
struct Curl_cftype *cft;
unsigned int category;
};
static struct trc_cft_def trc_cfts[] = {
{ &Curl_cft_tcp, TRC_CT_NETWORK },
{ &Curl_cft_udp, TRC_CT_NETWORK },
{ &Curl_cft_unix, TRC_CT_NETWORK },
{ &Curl_cft_tcp_accept, TRC_CT_NETWORK },
{ &Curl_cft_happy_eyeballs, TRC_CT_NETWORK },
{ &Curl_cft_setup, TRC_CT_PROTOCOL },
#ifdef USE_NGHTTP2
{ &Curl_cft_nghttp2, TRC_CT_PROTOCOL },
#endif
#ifdef USE_SSL
{ &Curl_cft_ssl, TRC_CT_NETWORK },
#ifndef CURL_DISABLE_PROXY
{ &Curl_cft_ssl_proxy, TRC_CT_PROXY },
#endif
#endif
#if !defined(CURL_DISABLE_PROXY)
#if !defined(CURL_DISABLE_HTTP)
{ &Curl_cft_h1_proxy, TRC_CT_PROXY },
#ifdef USE_NGHTTP2
{ &Curl_cft_h2_proxy, TRC_CT_PROXY },
#endif
{ &Curl_cft_http_proxy, TRC_CT_PROXY },
#endif /* !CURL_DISABLE_HTTP */
{ &Curl_cft_haproxy, TRC_CT_PROXY },
{ &Curl_cft_socks_proxy, TRC_CT_PROXY },
#endif /* !CURL_DISABLE_PROXY */
#ifdef USE_HTTP3
{ &Curl_cft_http3, TRC_CT_PROTOCOL },
connections: introduce http/3 happy eyeballs New cfilter HTTP-CONNECT for h3/h2/http1.1 eyeballing. - filter is installed when `--http3` in the tool is used (or the equivalent CURLOPT_ done in the library) - starts a QUIC/HTTP/3 connect right away. Should that not succeed after 100ms (subject to change), a parallel attempt is started for HTTP/2 and HTTP/1.1 via TCP - both attempts are subject to IPv6/IPv4 eyeballing, same as happens for other connections - tie timeout to the ip-version HAPPY_EYEBALLS_TIMEOUT - use a `soft` timeout at half the value. When the soft timeout expires, the HTTPS-CONNECT filter checks if the QUIC filter has received any data from the server. If not, it will start the HTTP/2 attempt. HTTP/3(ngtcp2) improvements. - setting call_data in all cfilter calls similar to http/2 and vtls filters for use in callback where no stream data is available. - returning CURLE_PARTIAL_FILE for prematurely terminated transfers - enabling pytest test_05 for h3 - shifting functionality to "connect" UDP sockets from ngtcp2 implementation into the udp socket cfilter. Because unconnected UDP sockets are weird. For example they error when adding to a pollset. HTTP/3(quiche) improvements. - fixed upload bug in quiche implementation, now passes 251 and pytest - error codes on stream RESET - improved debug logs - handling of DRAIN during connect - limiting pending event queue HTTP/2 cfilter improvements. - use LOG_CF macros for dynamic logging in debug build - fix CURLcode on RST streams to be CURLE_PARTIAL_FILE - enable pytest test_05 for h2 - fix upload pytests and improve parallel transfer performance. GOAWAY handling for ngtcp2/quiche - during connect, when the remote server refuses to accept new connections and closes immediately (so the local conn goes into DRAIN phase), the connection is torn down and a another attempt is made after a short grace period. This is the behaviour observed with nghttpx when we tell it to shut down gracefully. Tested in pytest test_03_02. TLS improvements - ALPN selection for SSL/SSL-PROXY filters in one vtls set of functions, replaces copy of logic in all tls backends. - standardized the infof logging of offered ALPNs - ALPN negotiated: have common function for all backends that sets alpn proprty and connection related things based on the negotiated protocol (or lack thereof). - new tests/tests-httpd/scorecard.py for testing h3/h2 protocol implementation. Invoke: python3 tests/tests-httpd/scorecard.py --help for usage. Improvements on gathering connect statistics and socket access. - new CF_CTRL_CONN_REPORT_STATS cfilter control for having cfilters report connection statistics. This is triggered when the connection has completely connected. - new void Curl_pgrsTimeWas(..) method to report a timer update with a timestamp of when it happend. This allows for updating timers "later", e.g. a connect statistic after full connectivity has been reached. - in case of HTTP eyeballing, the previous changes will update statistics only from the filter chain that "won" the eyeballing. - new cfilter query CF_QUERY_SOCKET for retrieving the socket used by a filter chain. Added methods Curl_conn_cf_get_socket() and Curl_conn_get_socket() for convenient use of this query. - Change VTLS backend to query their sub-filters for the socket when checks during the handshake are made. HTTP/3 documentation on how https eyeballing works. TLS improvements - ALPN selection for SSL/SSL-PROXY filters in one vtls set of functions, replaces copy of logic in all tls backends. - standardized the infof logging of offered ALPNs - ALPN negotiated: have common function for all backends that sets alpn proprty and connection related things based on the negotiated protocol (or lack thereof). Scorecard with Caddy. - configure can be run with `--with-test-caddy=path` to specify which caddy to use for testing - tests/tests-httpd/scorecard.py now measures download speeds with caddy pytest improvements - adding Makfile to clean gen dir - adding nghttpx rundir creation on start - checking httpd version 2.4.55 for test_05 cases where it is needed. Skipping with message if too old. - catch exception when checking for caddy existance on system. Closes #10349
2023-02-02 00:13:12 +08:00
#endif
#if !defined(CURL_DISABLE_HTTP)
{ &Curl_cft_http_connect, TRC_CT_PROTOCOL },
#endif
};
static void trc_apply_level_by_name(const char * const token, int lvl)
{
size_t i;
for(i = 0; i < ARRAYSIZE(trc_cfts); ++i) {
if(strcasecompare(token, trc_cfts[i].cft->name)) {
trc_cfts[i].cft->log_level = lvl;
break;
}
}
for(i = 0; i < ARRAYSIZE(trc_feats); ++i) {
if(strcasecompare(token, trc_feats[i].feat->name)) {
trc_feats[i].feat->log_level = lvl;
break;
}
}
}
static void trc_apply_level_by_category(int category, int lvl)
{
size_t i;
for(i = 0; i < ARRAYSIZE(trc_cfts); ++i) {
if(!category || (trc_cfts[i].category & category))
trc_cfts[i].cft->log_level = lvl;
}
for(i = 0; i < ARRAYSIZE(trc_feats); ++i) {
if(!category || (trc_feats[i].category & category))
trc_feats[i].feat->log_level = lvl;
}
}
static CURLcode trc_opt(const char *config)
{
char *token, *tok_buf, *tmp;
int lvl;
tmp = strdup(config);
if(!tmp)
return CURLE_OUT_OF_MEMORY;
token = Curl_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;
}
if(strcasecompare(token, "all"))
trc_apply_level_by_category(TRC_CT_NONE, lvl);
else if(strcasecompare(token, "protocol"))
trc_apply_level_by_category(TRC_CT_PROTOCOL, lvl);
else if(strcasecompare(token, "network"))
trc_apply_level_by_category(TRC_CT_NETWORK, lvl);
else if(strcasecompare(token, "proxy"))
trc_apply_level_by_category(TRC_CT_PROXY, lvl);
else
trc_apply_level_by_name(token, lvl);
token = Curl_strtok_r(NULL, ", ", &tok_buf);
}
free(tmp);
return CURLE_OK;
}
CURLcode Curl_trc_opt(const char *config)
{
CURLcode result = config ? trc_opt(config) : CURLE_OK;
#ifdef DEBUGBUILD
/* CURL_DEBUG can override anything */
if(!result) {
const char *dbg_config = getenv("CURL_DEBUG");
if(dbg_config)
result = trc_opt(dbg_config);
}
#endif /* DEBUGBUILD */
return result;
}
CURLcode Curl_trc_init(void)
{
#ifdef DEBUGBUILD
return Curl_trc_opt(NULL);
#else
return CURLE_OK;
#endif
}
#else /* defined(CURL_DISABLE_VERBOSE_STRINGS) */
CURLcode Curl_trc_init(void)
{
return CURLE_OK;
}
void Curl_infof(struct Curl_easy *data, const char *fmt, ...)
{
(void)data; (void)fmt;
}
void Curl_trc_cf_infof(struct Curl_easy *data,
struct Curl_cfilter *cf,
const char *fmt, ...)
{
(void)data; (void)cf; (void)fmt;
}
struct curl_trc_feat;
void Curl_trc_write(struct Curl_easy *data, const char *fmt, ...)
{
(void)data; (void)fmt;
}
void Curl_trc_read(struct Curl_easy *data, const char *fmt, ...)
{
(void)data; (void)fmt;
}
#ifndef CURL_DISABLE_FTP
void Curl_trc_ftp(struct Curl_easy *data, const char *fmt, ...)
{
(void)data; (void)fmt;
}
#endif
#ifndef CURL_DISABLE_SMTP
void Curl_trc_smtp(struct Curl_easy *data, const char *fmt, ...)
{
(void)data; (void)fmt;
}
#endif
#if !defined(CURL_DISABLE_WEBSOCKETS) || !defined(CURL_DISABLE_HTTP)
void Curl_trc_ws(struct Curl_easy *data, const char *fmt, ...)
{
(void)data; (void)fmt;
}
#endif
void Curl_trc_ssls(struct Curl_easy *data, const char *fmt, ...)
{
(void)data;
(void)fmt;
}
#endif /* !defined(CURL_DISABLE_VERBOSE_STRINGS) */