iv-org-mirror
/
litespeed-quic
mirror of https://gitea.invidious.io/iv-org/litespeed-quic.git
1
0
Fork 0
Code Issues Packages Projects Releases Wiki Activity

Merge 443677ab1b into 9c877a4177

This commit is contained in:
Hadi Frohar 2024-02-09 07:17:01 -07:00 committed by GitHub
parent 9c877a4177 443677ab1b
commit 4d131caadf
No known key found for this signature in database
GPG Key ID: B5690EEEBB952194
21 changed files with 125 additions and 121 deletions
Show Stats Download Patch File Download Diff File Expand all files Collapse all files

8
src/liblsquic/lsquic_bbr.c
View File

@ -733,8 +733,8 @@ maybe_exit_startup_or_drain (struct lsquic_bbr *bbr, lsquic_time_t now,
if (bbr->bbr_mode == BBR_MODE_DRAIN)
{
target_cwnd = get_target_cwnd(bbr, 1);
LSQ_DEBUG("%s: bytes in flight: %"PRIu64"; target cwnd: %"PRIu64,
__func__, bytes_in_flight, target_cwnd);
LSQ_DEBUG("bytes in flight: %"PRIu64"; target cwnd: %"PRIu64,
bytes_in_flight, target_cwnd);
if (bytes_in_flight <= target_cwnd)
enter_probe_bw_mode(bbr, now);
}
@ -799,9 +799,9 @@ maybe_enter_or_exit_probe_rtt (struct lsquic_bbr *bbr, lsquic_time_t now,
if (bbr->bbr_mode == BBR_MODE_PROBE_RTT)
{
lsquic_bw_sampler_app_limited(&bbr->bbr_bw_sampler);
LSQ_DEBUG("%s: exit probe at: %"PRIu64"; now: %"PRIu64
LSQ_DEBUG("exit probe at: %"PRIu64"; now: %"PRIu64
"; round start: %d; round passed: %d; rtt: %"PRIu64" usec",
__func__, bbr->bbr_exit_probe_rtt_at, now, is_round_start,
bbr->bbr_exit_probe_rtt_at, now, is_round_start,
!!(bbr->bbr_flags & BBR_FLAG_PROBE_RTT_ROUND_PASSED),
lsquic_rtt_stats_get_min_rtt(bbr->bbr_rtt_stats));
if (bbr->bbr_exit_probe_rtt_at == 0)

12
src/liblsquic/lsquic_cubic.c
View File

@ -109,7 +109,7 @@ cubic_update (struct lsquic_cubic *cubic, lsquic_time_t now, unsigned n_bytes)
void
lsquic_cubic_set_flags (struct lsquic_cubic *cubic, enum cubic_flags flags)
{
LSQ_DEBUG("%s(cubic, 0x%X)", __func__, flags);
LSQ_DEBUG("(cubic, 0x%X)", flags);
cubic->cu_flags = flags;
}
@ -132,7 +132,7 @@ lsquic_cubic_init (void *cong_ctl, const struct lsquic_conn_public *conn_pub,
else
#endif
cubic->cu_sampling_rate = 100000;
LSQ_DEBUG("%s(cubic, $conn)", __func__);
LSQ_DEBUG("(cubic, $conn)");
LSQ_INFO("initialized");
}
@ -163,7 +163,7 @@ static void
lsquic_cubic_was_quiet (void *cong_ctl, lsquic_time_t now, uint64_t in_flight)
{
struct lsquic_cubic *const cubic = cong_ctl;
LSQ_DEBUG("%s(cubic, %"PRIu64")", __func__, now);
LSQ_DEBUG("(cubic, %"PRIu64")", now);
cubic->cu_epoch_start = 0;
}
@ -176,7 +176,7 @@ lsquic_cubic_ack (void *cong_ctl, struct lsquic_packet_out *packet_out,
lsquic_time_t rtt;
rtt = now_time - packet_out->po_sent;
LSQ_DEBUG("%s(cubic, %"PRIu64", %"PRIu64", %d, %u)", __func__, now_time, rtt,
LSQ_DEBUG("(cubic, %"PRIu64", %"PRIu64", %d, %u)", now_time, rtt,
app_limited, n_bytes);
if (0 == cubic->cu_min_delay || rtt < cubic->cu_min_delay)
{
@ -203,7 +203,7 @@ static void
lsquic_cubic_loss (void *cong_ctl)
{
struct lsquic_cubic *const cubic = cong_ctl;
LSQ_DEBUG("%s(cubic)", __func__);
LSQ_DEBUG("(cubic)");
cubic->cu_epoch_start = 0;
if (FAST_CONVERGENCE && cubic->cu_cwnd < cubic->cu_last_max_cwnd)
cubic->cu_last_max_cwnd = cubic->cu_cwnd * TWO_MINUS_BETA_OVER_TWO / 1024;
@ -225,7 +225,7 @@ lsquic_cubic_timeout (void *cong_ctl)
unsigned long cwnd;
cwnd = cubic->cu_cwnd;
LSQ_DEBUG("%s(cubic)", __func__);
LSQ_DEBUG("(cubic)");
cubic_reset(cubic);
cubic->cu_ssthresh = cwnd / 2;
cubic->cu_tcp_cwnd = 2 * TCP_MSS;

2
src/liblsquic/lsquic_di_nocopy.c
View File

@ -386,7 +386,7 @@ nocopy_di_insert_frame (struct data_in *data_in,
ins_case = insert_frame(ncdi, new_frame, read_offset, &count);
ins = ins_case & 0xFF;
ins_case >>= 8;
LSQ_DEBUG("%s: ins: %d (case '%c')", __func__, ins, (char) ins_case);
LSQ_DEBUG("ins: %d (case '%c')", ins, (char) ins_case);
switch (ins)
{
case INS_FRAME_OK:

8
src/liblsquic/lsquic_enc_sess_ietf.c
View File

@ -1243,7 +1243,7 @@ setup_handshake_keys (struct enc_sess_iquic *enc_sess, const lsquic_cid_t *cid)
hp->hp_flags |= 1 << i;
else
{
LSQ_ERROR("%s: cannot initialize cipher %u", __func__, i);
LSQ_ERROR("cannot initialize cipher %u", i);
goto err;
}
}
@ -1569,7 +1569,7 @@ iquic_ssl_sess_to_resume_info (struct enc_sess_iquic *enc_sess, SSL *ssl,
if (!buf)
{
OPENSSL_free(ticket_buf);
LSQ_INFO("%s: malloc failed", __func__);
LSQ_INFO("malloc failed");
return -1;
}
@ -2604,7 +2604,7 @@ iquic_esf_global_init (int flags)
}
else
{
LSQ_LOG1(LSQ_LOG_ERROR, "%s: could not select index", __func__);
LSQ_LOG1(LSQ_LOG_ERROR, "could not select index");
return -1;
}
}
@ -3625,7 +3625,7 @@ lsquic_ssl_sess_to_resume_info (SSL *ssl, SSL_SESSION *session,
status = iquic_ssl_sess_to_resume_info(enc_sess, ssl, session, buf, buf_sz);
if (status == 0)
{
LSQ_DEBUG("%s called successfully, unset WANT_TICKET flag", __func__);
LSQ_DEBUG("called successfully, unset WANT_TICKET flag");
enc_sess->esi_flags &= ~ESI_WANT_TICKET;
lsquic_alarmset_unset(enc_sess->esi_alset, AL_SESS_TICKET);
}

12
src/liblsquic/lsquic_engine.c
View File

@ -963,7 +963,7 @@ destroy_conn (struct lsquic_engine *engine, struct lsquic_conn *conn,
if (engine->busy.current == conn)
{
char cidstr[MAX_CID_LEN * 2 + 1];
lsquic_logger_log1(LSQ_LOG_NOTICE, LSQLM_CONN_STATS,
lsquic_logger_log1(LSQ_LOG_NOTICE, LSQLM_CONN_STATS, __func__,
"busy connection %s is destroyed",
(lsquic_cid2str(lsquic_conn_log_cid(conn), cidstr), cidstr));
engine->busy.current = NULL;
@ -1040,7 +1040,7 @@ maybe_grow_conn_heaps (struct lsquic_engine *engine)
els = malloc(sizeof(els[0]) * count);
if (!els)
{
LSQ_ERROR("%s: malloc failed", __func__);
LSQ_ERROR("malloc failed");
return -1;
}
@ -1942,7 +1942,7 @@ lsquic_engine_connect (lsquic_engine_t *engine, enum lsquic_version version,
if (engine->flags & ENG_SERVER)
{
LSQ_ERROR("`%s' must only be called in client mode", __func__);
LSQ_ERROR("must only be called in client mode");
goto err;
}
@ -2894,7 +2894,7 @@ send_packets_out (struct lsquic_engine *engine,
coi_reheap(&conns_iter, engine);
LSQ_DEBUG("%s: sent %u packet%.*s", __func__, n_sent, n_sent != 1, "s");
LSQ_DEBUG("sent %u packet%.*s", n_sent, n_sent != 1, "s");
}
@ -3008,7 +3008,7 @@ maybe_log_conn_stats (struct lsquic_engine *engine, struct lsquic_conn *conn,
}
else
{
lsquic_logger_log1(LSQ_LOG_NOTICE, LSQLM_CONN_STATS,
lsquic_logger_log1(LSQ_LOG_NOTICE, LSQLM_CONN_STATS, __func__,
"stop logging status for connection %s: no longer busy",
(lsquic_cid2str(lsquic_conn_log_cid(conn), cidstr), cidstr));
engine->busy.current = NULL;
@ -3333,7 +3333,7 @@ update_busy_detector (struct lsquic_engine *engine, struct lsquic_conn *conn,
if (MAX_IMMED_TICKS == engine->busy.immed_ticks)
{
if (engine->busy.current != conn)
lsquic_logger_log1(LSQ_LOG_NOTICE, LSQLM_CONN_STATS,
lsquic_logger_log1(LSQ_LOG_NOTICE, LSQLM_CONN_STATS, __func__,
"connection %s marked busy: it's had %u immediate ticks "
"in a row",
(lsquic_cid2str(lsquic_conn_log_cid(conn), cidstr), cidstr),

6
src/liblsquic/lsquic_ev_log.h
View File

@ -23,13 +23,15 @@ struct stack_st_X509;
/* Log a generic event not tied to any particular connection */
#define EV_LOG_GENERIC_EVENT(...) do { \
if (LSQ_LOG_ENABLED_EXT(LSQ_LOG_DEBUG, LSQLM_EVENT)) \
lsquic_logger_log1(LSQ_LOG_DEBUG, LSQLM_EVENT, __VA_ARGS__); \
lsquic_logger_log1(LSQ_LOG_DEBUG, LSQLM_EVENT, \
__func__, __VA_ARGS__); \
} while (0)
/* Log a generic event associated with connection `cid' */
#define EV_LOG_CONN_EVENT(cid, ...) do { \
if (LSQ_LOG_ENABLED_EXT(LSQ_LOG_DEBUG, LSQLM_EVENT)) \
lsquic_logger_log2(LSQ_LOG_DEBUG, LSQLM_EVENT, cid, __VA_ARGS__); \
lsquic_logger_log2(LSQ_LOG_DEBUG, LSQLM_EVENT, cid, \
__func__, __VA_ARGS__); \
} while (0)
void

6
src/liblsquic/lsquic_frame_reader.c
View File

@ -230,12 +230,12 @@ lsquic_frame_reader_destroy (struct lsquic_frame_reader *fr)
assert(nread <= 0); \
if (0 == nread) \
{ \
LSQ_INFO("%s: unexpected EOF", __func__); \
LSQ_INFO("unexpected EOF"); \
return -1; \
} \
else \
{ \
LSQ_WARN("%s: error reading from stream: %s", __func__, \
LSQ_WARN("error reading from stream: %s", \
strerror(errno)); \
return -1; \
} \
@ -690,7 +690,7 @@ decode_and_pass_payload (struct lsquic_frame_reader *fr)
return;
stream_error:
LSQ_INFO("%s: stream error %u", __func__, err);
LSQ_INFO("stream error %u", err);
if (hset)
fr->fr_hsi_if->hsi_discard_header_set(hset);
fr->fr_callbacks->frc_on_error(fr->fr_cb_ctx, fr_get_stream_id(fr), err);

12
src/liblsquic/lsquic_full_conn.c
View File

@ -2951,7 +2951,7 @@ create_delayed_streams (struct full_conn *conn)
new_streams = malloc(sizeof(new_streams[0]) * avail);
if (!new_streams)
{
ABORT_WARN("%s: malloc failed", __func__);
ABORT_WARN("malloc failed");
return;
}
@ -2964,8 +2964,7 @@ create_delayed_streams (struct full_conn *conn)
new_streams[i] = new_stream(conn, generate_stream_id(conn), 0);
if (!new_streams[i])
{
ABORT_ERROR("%s: cannot create new stream: %s", __func__,
strerror(errno));
ABORT_ERROR("cannot create new stream: %s", strerror(errno));
goto cleanup;
}
}
@ -3262,7 +3261,7 @@ immediate_close (struct full_conn *conn)
lsquic_packet_out_avail(packet_out), 0, error_code,
error_reason, error_reason ? strlen(error_reason) : 0);
if (sz < 0) {
LSQ_WARN("%s failed", __func__);
LSQ_WARN("failed");
return TICK_CLOSE;
}
lsquic_send_ctl_incr_pack_sz(&conn->fc_send_ctl, packet_out, sz);
@ -4365,8 +4364,7 @@ full_conn_ci_next_tick_time (lsquic_conn_t *lconn, unsigned *why)
{
now = lsquic_time_now();
if (pacer_time < now)
LSQ_DEBUG("%s: pacer is %"PRIu64" usec in the past", __func__,
now - pacer_time);
LSQ_DEBUG("pacer is %"PRIu64" usec in the past", now - pacer_time);
}
if (alarm_time && pacer_time)
@ -4500,7 +4498,7 @@ full_conn_ci_log_stats (struct lsquic_conn *lconn)
cwnd = conn->fc_send_ctl.sc_ci->cci_get_cwnd(
conn->fc_send_ctl.sc_cong_ctl);
lsquic_conn_stats_diff(&conn->fc_stats, conn->fc_last_stats, &diff_stats);
lsquic_logger_log1(LSQ_LOG_NOTICE, LSQLM_CONN_STATS,
lsquic_logger_log1(LSQ_LOG_NOTICE, LSQLM_CONN_STATS, __func__,
"%s: ticks: %lu; cwnd: %"PRIu64"; conn flow: max: %"PRIu64
", avail: %"PRIu64"; packets: sent: %lu, lost: %lu, retx: %lu, rcvd: %lu"
"; batch: count: %u; min: %u; max: %u; avg: %.2f",

24
src/liblsquic/lsquic_full_conn_ietf.c
View File

@ -695,7 +695,7 @@ cid_throt_alarm_expired (enum alarm_id al_id, void *ctx,
lsquic_time_t expiry, lsquic_time_t now)
{
struct ietf_full_conn *const conn = (struct ietf_full_conn *) ctx;
LSQ_DEBUG("%s", __func__);
LSQ_DEBUG("called");
conn->ifc_send_flags |= SF_SEND_NEW_CID;
return;
}
@ -1803,7 +1803,7 @@ generate_timestamp_frame (struct ietf_full_conn *conn,
if (0 != lsquic_packet_out_add_frame(packet_out, conn->ifc_pub.mm, 0,
QUIC_FRAME_TIMESTAMP, packet_out->po_data_sz, w))
{
LSQ_DEBUG("%s: adding frame to packet failed: %d", __func__, errno);
LSQ_DEBUG("adding frame to packet failed: %d", errno);
return;
}
packet_out->po_frame_types |= 1 << QUIC_FRAME_TIMESTAMP;
@ -3047,7 +3047,7 @@ retire_seqno (struct ietf_full_conn *conn, unsigned seqno)
conn->ifc_send_flags |= SF_SEND_RETIRE_CID;
}
else
LSQ_INFO("%s: cannot allocate dce", __func__);
LSQ_INFO("cannot allocate dce");
}
@ -3082,7 +3082,7 @@ ietf_full_conn_ci_retire_cid (struct lsquic_conn *lconn)
}
if (!dces[1])
{
ABORT_WARN("%s: cannot find own DCID", __func__);
ABORT_WARN("cannot find own DCID");
return;
}
if (!dces[0])
@ -4307,13 +4307,13 @@ immediate_close (struct ietf_full_conn *conn)
conn_err.u.err, error_reason,
error_reason ? strlen(error_reason) : 0);
if (sz < 0) {
LSQ_WARN("%s failed", __func__);
LSQ_WARN("failed");
return TICK_CLOSE;
}
if (0 != lsquic_packet_out_add_frame(packet_out, conn->ifc_pub.mm, 0,
QUIC_FRAME_CONNECTION_CLOSE, packet_out->po_data_sz, sz))
{
LSQ_WARN("%s: adding frame to packet failed: %d", __func__, errno);
LSQ_WARN("adding frame to packet failed: %d", errno);
return TICK_CLOSE;
}
lsquic_send_ctl_incr_pack_sz(&conn->ifc_send_ctl, packet_out, sz);
@ -4883,8 +4883,7 @@ ietf_full_conn_ci_next_tick_time (struct lsquic_conn *lconn, unsigned *why)
{
now = lsquic_time_now();
if (pacer_time < now)
LSQ_DEBUG("%s: pacer is %"PRIu64" usec in the past", __func__,
now - pacer_time);
LSQ_DEBUG("pacer is %"PRIu64" usec in the past", now - pacer_time);
}
if (alarm_time && pacer_time)
@ -7173,15 +7172,14 @@ verify_retry_packet (struct ietf_full_conn *conn,
/* Cover the theoretical possibility that we cannot fit the pseudo-
* packet and 16-byte decrypted output into 4 KB:
*/
LSQ_INFO("%s: Retry packet is too long: %hu bytes", __func__,
packet_in->pi_data_sz);
LSQ_INFO("Retry packet is too long: %hu bytes", packet_in->pi_data_sz);
return -1;
}
pseudo_packet = lsquic_mm_get_4k(conn->ifc_pub.mm);
if (!pseudo_packet)
{
LSQ_INFO("%s: cannot allocate memory", __func__);
LSQ_INFO("cannot allocate memory");
return -1;
}
@ -7326,7 +7324,7 @@ on_dcid_change (struct ietf_full_conn *conn, const lsquic_cid_t *dcid_in)
cce->cce_flags |= CCE_USED;
lconn->cn_cur_cce_idx = cce - lconn->cn_cces;
LSQ_DEBUGC("%s: set SCID to %"CID_FMT, __func__, CID_BITS(CN_SCID(lconn)));
LSQ_DEBUGC("set SCID to %"CID_FMT, CID_BITS(CN_SCID(lconn)));
LOG_SCIDS(conn);
return 0;
@ -8973,7 +8971,7 @@ ietf_full_conn_ci_log_stats (struct lsquic_conn *lconn)
cwnd = conn->ifc_send_ctl.sc_ci->cci_get_cwnd(
conn->ifc_send_ctl.sc_cong_ctl);
lsquic_conn_stats_diff(&conn->ifc_stats, conn->ifc_last_stats, &diff_stats);
lsquic_logger_log1(LSQ_LOG_NOTICE, LSQLM_CONN_STATS,
lsquic_logger_log1(LSQ_LOG_NOTICE, LSQLM_CONN_STATS, __func__,
"%s: ticks: %lu; cwnd: %"PRIu64"; conn flow: max: %"PRIu64
", avail: %"PRIu64"; packets: sent: %lu, lost: %lu, retx: %lu, rcvd: %lu"
"; batch: count: %u; min: %u; max: %u; avg: %.2f",

12
src/liblsquic/lsquic_handshake.c
View File

@ -1880,7 +1880,7 @@ get_valid_scfg (const struct lsquic_enc_session *enc_session,
temp_scfg->scfg_len = MSG_LEN_VAL(msg_len);
LSQ_DEBUG("%s called, return len %d.", __func__, temp_scfg->scfg_len);
LSQ_DEBUG("called, return len %d.", temp_scfg->scfg_len);
// /* TODO: will shi_delete call free to release the buffer? */
// shi->shi_delete(shi_ctx, SERVER_SCFG_KEY, SERVER_SCFG_KEY_SIZE);
@ -2870,8 +2870,7 @@ lsquic_enc_session_handle_chlo_reply (enc_session_t *enc_session_p,
end:
LSQ_DEBUG("lsquic_enc_session_handle_chlo_reply called, buf in %d, return %d.", len, ret);
EV_LOG_CONN_EVENT(&enc_session->cid, "%s returning %s", __func__,
he2str(ret));
EV_LOG_CONN_EVENT(&enc_session->cid, "returning %s", he2str(ret));
return ret;
}
@ -3226,9 +3225,9 @@ gquic_encrypt_buf (struct lsquic_enc_session *enc_session,
EVP_AEAD_CTX *key;
if (enc_session)
LSQ_DEBUG("%s: hsk_state: %d", __func__, enc_session->hsk_state);
LSQ_DEBUG("hsk_state: %d", enc_session->hsk_state);
else
LSQ_DEBUG("%s: enc_session is not set", __func__);
LSQ_DEBUG("enc_session is not set");
if (!enc_session || enc_session->have_key == 0 || is_chlo)
{
@ -3361,8 +3360,7 @@ lsquic_enc_session_handle_chlo(enc_session_t *enc_session_p,
}
end:
EV_LOG_CONN_EVENT(&enc_session->cid, "%s returning %s", __func__,
he2str(rtt));
EV_LOG_CONN_EVENT(&enc_session->cid, "returning %s", he2str(rtt));
return rtt;
}

3
src/liblsquic/lsquic_hpi.c
View File

@ -327,8 +327,7 @@ lsquic_hpi_next (void *iter_p)
stream = next_nonincr(iter, prio);
if (LSQ_LOG_ENABLED(LSQ_LOG_DEBUG))
HPI_DEBUG("%s: return stream %"PRIu64", incr: %u, priority %u",
__func__, stream->id, incr, prio);
HPI_DEBUG("return stream %"PRIu64", incr: %u, priority %u", stream->id, incr, prio);
return stream;
}

26
src/liblsquic/lsquic_logger.c
View File

@ -245,7 +245,7 @@ void
lsquic_logger_log3 (enum lsq_log_level log_level,
enum lsquic_logger_module module,
const lsquic_cid_t *conn_id, lsquic_stream_id_t stream_id,
const char *fmt, ...)
const char *caller, const char *fmt, ...)
{
const int saved_errno = errno;
char cidbuf_[MAX_CID_LEN * 2 + 1];
@ -261,9 +261,9 @@ lsquic_logger_log3 (enum lsq_log_level log_level,
goto end;
len += lb;
}
lb = snprintf(buf + len, max - len, "[%s] [QUIC:%"CID_FMT"-%"PRIu64"] %s: ",
lb = snprintf(buf + len, max - len, "[%s] [QUIC:%"CID_FMT"-%"PRIu64"] %s::%s: ",
lsq_loglevel2str[log_level], CID_BITS(conn_id),
stream_id, lsqlm_to_str[module]);
stream_id, lsqlm_to_str[module], caller);
if (FORMAT_PROBLEM(lb, len, max))
goto end;
len += lb;
@ -292,7 +292,8 @@ end:
void
lsquic_logger_log2 (enum lsq_log_level log_level,
enum lsquic_logger_module module,
const struct lsquic_cid *conn_id, const char *fmt, ...)
const struct lsquic_cid *conn_id, const char *caller,
const char *fmt, ...)
{
const int saved_errno = errno;
char cidbuf_[MAX_CID_LEN * 2 + 1];
@ -309,8 +310,8 @@ lsquic_logger_log2 (enum lsq_log_level log_level,
len += lb;
}
lb = snprintf(buf + len, max - len, "[%s] [QUIC:%"CID_FMT"] %s: ",
lsq_loglevel2str[log_level], CID_BITS(conn_id), lsqlm_to_str[module]);
lb = snprintf(buf + len, max - len, "[%s] [QUIC:%"CID_FMT"] %s::%s: ",
lsq_loglevel2str[log_level], CID_BITS(conn_id), lsqlm_to_str[module], caller);
if (FORMAT_PROBLEM(lb, len, max))
goto end;
len += lb;
@ -339,7 +340,7 @@ end:
void
lsquic_logger_log1 (enum lsq_log_level log_level,
enum lsquic_logger_module module,
const char *fmt, ...)
const char *caller, const char *fmt, ...)
{
const int saved_errno = errno;
size_t len = 0;
@ -354,8 +355,8 @@ lsquic_logger_log1 (enum lsq_log_level log_level,
goto end;
len += lb;
}
lb = snprintf(buf + len, max - len, "[%s] %s: ", lsq_loglevel2str[log_level],
lsqlm_to_str[module]);
lb = snprintf(buf + len, max - len, "[%s] %s::%s: ", lsq_loglevel2str[log_level],
lsqlm_to_str[module], caller);
if (FORMAT_PROBLEM(lb, len, max))
goto end;
len += lb;
@ -382,7 +383,8 @@ end:
void
lsquic_logger_log0 (enum lsq_log_level log_level, const char *fmt, ...)
lsquic_logger_log0 (enum lsq_log_level log_level, const char *caller,
const char *fmt, ...)
{
const int saved_errno = errno;
size_t len = 0;
@ -398,7 +400,7 @@ lsquic_logger_log0 (enum lsq_log_level log_level, const char *fmt, ...)
len += lb;
}
lb = snprintf(buf + len, max - len, "[%s] ", lsq_loglevel2str[log_level]);
lb = snprintf(buf + len, max - len, "[%s] %s: ", lsq_loglevel2str[log_level], caller);
if (FORMAT_PROBLEM(lb, len, max))
goto end;
len += lb;
@ -432,7 +434,7 @@ lsquic_logger_init (const struct lsquic_logger_if *lif, void *lctx,
logger_ctx = lctx;
if (llts < N_LLTS)
g_llts = llts;
LSQ_DEBUG("%s called", __func__);
LSQ_DEBUG("called");
}

38
src/liblsquic/lsquic_logger.h
View File

@ -129,73 +129,81 @@ struct lsquic_cid;
void
lsquic_logger_log3 (enum lsq_log_level, enum lsquic_logger_module,
const struct lsquic_cid *conn_id,
lsquic_stream_id_t stream_id, const char *format, ...)
lsquic_stream_id_t stream_id, const char *caller,
const char *format, ...)
#if __GNUC__
__attribute__((format(printf, 5, 6)))
__attribute__((format(printf, 6, 7)))
#endif
;
# define LSQ_LOG3(level, ...) do { \
if (LSQ_LOG_ENABLED(level)) \
lsquic_logger_log3(level, LSQUIC_LOGGER_MODULE, \
LSQUIC_LOG_CONN_ID, LSQUIC_LOG_STREAM_ID, __VA_ARGS__); \
LSQUIC_LOG_CONN_ID, LSQUIC_LOG_STREAM_ID, __func__, \
__VA_ARGS__); \
} while (0)
void
lsquic_logger_log2 (enum lsq_log_level, enum lsquic_logger_module,
const struct lsquic_cid *conn_id, const char *format, ...)
const struct lsquic_cid *conn_id, const char *caller,
const char *format, ...)
#if __GNUC__
__attribute__((format(printf, 4, 5)))
__attribute__((format(printf, 5, 6)))
#endif
;
# define LSQ_LOG2(level, ...) do { \
if (LSQ_LOG_ENABLED(level)) \
lsquic_logger_log2(level, LSQUIC_LOGGER_MODULE, \
LSQUIC_LOG_CONN_ID, __VA_ARGS__); \
LSQUIC_LOG_CONN_ID, __func__, \
__VA_ARGS__); \
} while (0)
# define LSQ_LOG2C(level, ...) do { \
if (LSQ_LOG_ENABLED(level)) \
{ \
char cidbuf_[MAX_CID_LEN * 2 + 1]; \
lsquic_logger_log2(level, LSQUIC_LOGGER_MODULE, \
LSQUIC_LOG_CONN_ID, __VA_ARGS__); \
LSQUIC_LOG_CONN_ID, __func__, \
__VA_ARGS__); \
} \
} while (0)
void
lsquic_logger_log1 (enum lsq_log_level, enum lsquic_logger_module,
const char *format, ...)
const char *caller, const char *format, ...)
#if __GNUC__
__attribute__((format(printf, 3, 4)))
__attribute__((format(printf, 4, 5)))
#endif
;
# define LSQ_LOG1(level, ...) do { \
if (LSQ_LOG_ENABLED(level)) \
lsquic_logger_log1(level, LSQUIC_LOGGER_MODULE, __VA_ARGS__); \
lsquic_logger_log1(level, LSQUIC_LOGGER_MODULE, \
__func__, __VA_ARGS__); \
} while (0)
# define LSQ_LOG1C(level, ...) do { \
if (LSQ_LOG_ENABLED(level)) \
{ \
char cidbuf_[MAX_CID_LEN * 2 + 1]; \
lsquic_logger_log1(level, LSQUIC_LOGGER_MODULE, __VA_ARGS__); \
lsquic_logger_log1(level, LSQUIC_LOGGER_MODULE, \
__func__, __VA_ARGS__); \
} \
} while (0)
void
lsquic_logger_log0 (enum lsq_log_level, const char *format, ...)
lsquic_logger_log0 (enum lsq_log_level, const char *caller,
const char *format, ...)
#if __GNUC__
__attribute__((format(printf, 2, 3)))
__attribute__((format(printf, 3, 4)))
#endif
;
# define LSQ_LOG0(level, ...) do { \
if (LSQ_LOG_ENABLED(level)) \
lsquic_logger_log0(level, __VA_ARGS__); \
lsquic_logger_log0(level, __func__, __VA_ARGS__); \
} while (0)
# define LSQ_LOG0C(level, ...) do { \
if (LSQ_LOG_ENABLED(level)) \
{ \
char cidbuf_[MAX_CID_LEN * 2 + 1]; \
lsquic_logger_log0(level, __VA_ARGS__); \
lsquic_logger_log0(level, __func__, __VA_ARGS__); \
} \
} while (0)

13
src/liblsquic/lsquic_mini_conn.c
View File

@ -1289,8 +1289,7 @@ mini_rechist_largest_recv (void *rechist_ctx)
lsquic_time_t delta = mc->mc_largest_recv[0]
+ (mc->mc_largest_recv[1] << 8)
+ (mc->mc_largest_recv[2] << 16);
LSQ_DEBUG("%s: largest received: %"PRIu64" usec since creation",
__func__, delta);
LSQ_DEBUG("largest received: %"PRIu64" usec since creation", delta);
return mc->mc_created + delta;
}
@ -1328,7 +1327,7 @@ mini_rechist_next (void *rechist_ctx)
}
else
rechist->cur_set = 0;
LSQ_DEBUG("%s: return [%"PRIu64", %"PRIu64"]", __func__,
LSQ_DEBUG("return [%"PRIu64", %"PRIu64"]",
rechist->range.low, rechist->range.high);
return &rechist->range;
}
@ -1354,7 +1353,7 @@ least_unacked (const struct mini_conn *mc)
packno = lowest_bit_set(unacked) + 1;
else
packno = highest_bit_set(mc->mc_sent_packnos) + 2;
LSQ_DEBUG("%s: least unacked: %"PRIu64, __func__, packno);
LSQ_DEBUG("least unacked: %"PRIu64, packno);
return packno;
}
@ -1958,7 +1957,7 @@ mini_conn_ci_packet_sent (struct lsquic_conn *lconn,
assert(mc->mc_flags & MC_UNSENT_ACK);
mc->mc_flags &= ~MC_UNSENT_ACK;
}
LSQ_DEBUG("%s: packet %"PRIu64" sent", __func__, packet_out->po_packno);
LSQ_DEBUG("packet %"PRIu64" sent", packet_out->po_packno);
MCHIST_APPEND(mc, MCHE_PACKET_SENT);
}
@ -1969,7 +1968,7 @@ mini_conn_ci_packet_not_sent (struct lsquic_conn *lconn,
{
struct mini_conn *mc = (struct mini_conn *) lconn;
packet_out->po_flags &= ~PO_SENT;
LSQ_DEBUG("%s: packet %"PRIu64" not sent", __func__, packet_out->po_packno);
LSQ_DEBUG("packet %"PRIu64" not sent", packet_out->po_packno);
MCHIST_APPEND(mc, MCHE_PACKET_DELAYED);
}
@ -2062,7 +2061,7 @@ mini_conn_ci_destroy (struct lsquic_conn *lconn)
#else
if (LSQ_LOG_ENABLED(log_level))
lsquic_logger_log2(log_level, LSQUIC_LOGGER_MODULE,
LSQUIC_LOG_CONN_ID,
LSQUIC_LOG_CONN_ID, __func__,
"destroyed. Diagnostics: conn flags: 0x%X, "
"mc flags: 0x%X, "
#if LSQUIC_RECORD_INORD_HIST

6
src/liblsquic/lsquic_mini_conn_ietf.c
View File

@ -1818,7 +1818,7 @@ ietf_mini_conn_ci_packet_sent (struct lsquic_conn *lconn,
#endif
if (packet_out->po_header_type == HETY_HANDSHAKE)
conn->imc_flags |= IMC_HSK_PACKET_SENT;
LSQ_DEBUG("%s: packet %"PRIu64" sent", __func__, packet_out->po_packno);
LSQ_DEBUG("packet %"PRIu64" sent", packet_out->po_packno);
}
@ -1832,7 +1832,7 @@ ietf_mini_conn_ci_packet_not_sent (struct lsquic_conn *lconn,
packet_out->po_flags &= ~PO_SENT;
packet_size = lsquic_packet_out_total_sz(lconn, packet_out);
conn->imc_bytes_out -= packet_size;
LSQ_DEBUG("%s: packet %"PRIu64" not sent", __func__, packet_out->po_packno);
LSQ_DEBUG("packet %"PRIu64" not sent", packet_out->po_packno);
}
@ -2002,7 +2002,7 @@ imico_bitmask_rechist_next (struct ietf_mini_rechist *rechist)
}
else
rechist->u.bitmask.cur_set = 0;
LSQ_DEBUG("%s: return [%"PRIu64", %"PRIu64"]", __func__,
LSQ_DEBUG("return [%"PRIu64", %"PRIu64"]",
rechist->u.bitmask.range.low, rechist->u.bitmask.range.high);
return &rechist->u.bitmask.range;
}

8
src/liblsquic/lsquic_pacer.c
View File

@ -59,7 +59,7 @@ lsquic_pacer_packet_scheduled (struct pacer *pacer, unsigned n_in_flight,
if (n_in_flight == 0 && !in_recovery)
{
pacer->pa_burst_tokens = 10;
LSQ_DEBUG("%s: replenish tokens: %u", __func__, pacer->pa_burst_tokens);
LSQ_DEBUG("replenish tokens: %u", pacer->pa_burst_tokens);
}
if (pacer->pa_burst_tokens > 0)
@ -68,7 +68,7 @@ lsquic_pacer_packet_scheduled (struct pacer *pacer, unsigned n_in_flight,
pacer->pa_flags &= ~PA_LAST_SCHED_DELAYED;
pacer->pa_next_sched = 0;
pacer->pa_last_delayed = 0;
LSQ_DEBUG("%s: tokens: %u", __func__, pacer->pa_burst_tokens);
LSQ_DEBUG("tokens: %u", pacer->pa_burst_tokens);
return;
}
@ -101,7 +101,7 @@ void
lsquic_pacer_loss_event (struct pacer *pacer)
{
pacer->pa_burst_tokens = 0;
LSQ_DEBUG("%s: tokens: %u", __func__, pacer->pa_burst_tokens);
LSQ_DEBUG("tokens: %u", pacer->pa_burst_tokens);
}
@ -120,7 +120,7 @@ lsquic_pacer_can_schedule (struct pacer *pacer, unsigned n_in_flight)
else
can = 1;
LSQ_DEBUG("%s: %d", __func__, can);
LSQ_DEBUG("%d", can);
return can;
}

2
src/liblsquic/lsquic_parse_gquic_be.c
View File

@ -919,7 +919,7 @@ lsquic_gquic_be_gen_ack_frame (unsigned char *outbuf, size_t outbuf_sz,
CHECKOUT(2);
time_diff = now - rechist_largest_recv(rechist);
lsquic_gquic_be_write_float_time16(time_diff, p);
LSQ_DEBUG("%s: diff: %"PRIu64"; encoded: 0x%04X", __func__, time_diff,
LSQ_DEBUG("diff: %"PRIu64"; encoded: 0x%04X", time_diff,
*(uint16_t*)p);
p += 2;

4
src/liblsquic/lsquic_qdec_hdl.c
View File

@ -143,7 +143,7 @@ qdh_begin_out (struct qpack_dec_hdl *qdh)
{
if (0 != qdh_write_type(qdh))
{
LSQ_WARN("%s: could not write to decoder", __func__);
LSQ_WARN("could not write to decoder");
qdh->qdh_conn->cn_if->ci_internal_error(qdh->qdh_conn,
"cannot write to decoder stream");
}
@ -280,7 +280,7 @@ qdh_out_on_write (struct lsquic_stream *stream, lsquic_stream_ctx_t *ctx)
if (lsquic_frab_list_empty(&qdh->qdh_fral))
{
LSQ_DEBUG("%s: nothing to write", __func__);
LSQ_DEBUG("nothing to write");
lsquic_stream_wantwrite(stream, 0);
return;
}

10
src/liblsquic/lsquic_send_ctl.c
View File

@ -1705,8 +1705,8 @@ static int
send_ctl_can_send (struct lsquic_send_ctl *ctl)
{
const unsigned n_out = send_ctl_all_bytes_out(ctl);
LSQ_DEBUG("%s: n_out: %u (unacked_all: %u); cwnd: %"PRIu64
"; ccfc: %"PRIu64"/%"PRIu64, __func__,
LSQ_DEBUG("n_out: %u (unacked_all: %u); cwnd: %"PRIu64
"; ccfc: %"PRIu64"/%"PRIu64,
n_out, ctl->sc_bytes_unacked_all,
ctl->sc_ci->cci_get_cwnd(CGP(ctl)),
ctl->sc_conn_pub->conn_cap.cc_sent,
@ -1742,8 +1742,8 @@ send_ctl_can_send_pre_hsk (struct lsquic_send_ctl *ctl)
if (bytes_out >= bytes_in * 2 + bytes_in / 2 /* This should work out
to around 3 on average */)
{
LSQ_DEBUG("%s: amplification block: %u bytes in, %u bytes out",
__func__, bytes_in, bytes_out);
LSQ_DEBUG("amplification block: %u bytes in, %u bytes out",
bytes_in, bytes_out);
return 0;
}
else
@ -2601,7 +2601,7 @@ send_ctl_log_packet_q (const lsquic_send_ctl_t *ctl, const char *prefix,
buf = malloc(bufsz);
if (!buf)
{
LSQ_ERROR("%s: malloc: %s", __func__, strerror(errno));
LSQ_ERROR("malloc: %s", strerror(errno));
return;
}

18
src/liblsquic/lsquic_spi.c
View File

@ -119,7 +119,7 @@ find_and_set_lowest_priority (struct stream_prio_iter *iter)
if (set >= 4)
{
//SPI_DEBUG("%s: cannot find any", __func__);
//SPI_DEBUG("cannot find any");
return -1;
}
@ -138,7 +138,7 @@ find_and_set_lowest_priority (struct stream_prio_iter *iter)
assert(iter->spi_set[ set ] & (1ULL << bit));
#endif
SPI_DEBUG("%s: prio %u -> %u", __func__, iter->spi_cur_prio, prio);
SPI_DEBUG("prio %u -> %u", iter->spi_cur_prio, prio);
iter->spi_cur_prio = (unsigned char) prio;
return 0;
}
@ -171,7 +171,7 @@ find_and_set_next_priority (struct stream_prio_iter *iter)
if (set >= 4)
{
//SPI_DEBUG("%s: cannot find any", __func__);
//SPI_DEBUG("cannot find any");
return -1;
}
@ -191,7 +191,7 @@ find_and_set_next_priority (struct stream_prio_iter *iter)
assert(iter->spi_set[ set ] & (1ULL << bit));
#endif
SPI_DEBUG("%s: prio %u -> %u", __func__, iter->spi_cur_prio, prio);
SPI_DEBUG("prio %u -> %u", iter->spi_cur_prio, prio);
iter->spi_cur_prio = (unsigned char) prio;
return 0;
}
@ -212,7 +212,7 @@ lsquic_spi_first (void *iter_p)
{
if (0 != find_and_set_lowest_priority(iter))
{
SPI_DEBUG("%s: return NULL", __func__);
SPI_DEBUG("return NULL, iter_p=%p", iter_p);
return NULL;
}
}
@ -220,7 +220,7 @@ lsquic_spi_first (void *iter_p)
stream = TAILQ_FIRST(&iter->spi_streams[ iter->spi_cur_prio ]);
iter->spi_next_stream = TAILQ_NEXT(stream, next_prio_stream);
if (LSQ_LOG_ENABLED(LSQ_LOG_DEBUG) && !lsquic_stream_is_critical(stream))
SPI_DEBUG("%s: return stream %"PRIu64", priority %u", __func__,
SPI_DEBUG("return stream %"PRIu64", priority %u",
stream->id, iter->spi_cur_prio);
return stream;
}
@ -237,14 +237,14 @@ lsquic_spi_next (void *iter_p)
{
iter->spi_next_stream = TAILQ_NEXT(stream, next_prio_stream);
if (LSQ_LOG_ENABLED(LSQ_LOG_DEBUG) && !lsquic_stream_is_critical(stream))
SPI_DEBUG("%s: return stream %"PRIu64", priority %u", __func__,
SPI_DEBUG("return stream %"PRIu64", priority %u",
stream->id, iter->spi_cur_prio);
return stream;
}
if (0 != find_and_set_next_priority(iter))
{
//SPI_DEBUG("%s: return NULL", __func__);
//SPI_DEBUG("return NULL");
return NULL;
}
@ -252,7 +252,7 @@ lsquic_spi_next (void *iter_p)
iter->spi_next_stream = TAILQ_NEXT(stream, next_prio_stream);
if (LSQ_LOG_ENABLED(LSQ_LOG_DEBUG) && !lsquic_stream_is_critical(stream))
SPI_DEBUG("%s: return stream %"PRIu64", priority %u", __func__,
SPI_DEBUG("return stream %"PRIu64", priority %u",
stream->id, iter->spi_cur_prio);
return stream;
}

16
src/liblsquic/lsquic_stream.c
View File

@ -1657,8 +1657,8 @@ stream_readf (struct lsquic_stream *stream,
return nread;
total_nread += (size_t) nread;
LSQ_DEBUG("%s: read %zd bytes, read offset %"PRIu64", reached fin: %d",
__func__, total_nread, stream->read_offset,
LSQ_DEBUG("read %zd bytes, read offset %"PRIu64", reached fin: %d",
total_nread, stream->read_offset,
!!(stream->stream_flags & STREAM_FIN_REACHED));
if (total_nread)
@ -3122,7 +3122,7 @@ verify_conn_cap (const struct lsquic_conn_public *conn_pub)
assert(n_buffered + conn_pub->stream_frame_bytes
== conn_pub->conn_cap.cc_sent);
LSQ_DEBUG("%s: cc_sent: %"PRIu64, __func__, conn_pub->conn_cap.cc_sent);
LSQ_DEBUG("cc_sent: %"PRIu64, conn_pub->conn_cap.cc_sent);
}
@ -4724,7 +4724,7 @@ lsquic_stream_get_hset (struct lsquic_stream *stream)
if (stream_is_read_reset(stream))
{
LSQ_INFO("%s: stream is reset, no headers returned", __func__);
LSQ_INFO("stream is reset, no headers returned");
errno = ECONNRESET;
return NULL;
}
@ -4732,14 +4732,14 @@ lsquic_stream_get_hset (struct lsquic_stream *stream)
if (!((stream->sm_bflags & SMBF_USE_HEADERS)
&& (stream->stream_flags & STREAM_HAVE_UH)))
{
LSQ_INFO("%s: unexpected call, flags: 0x%X", __func__,
LSQ_INFO("unexpected call, flags: 0x%X",
stream->stream_flags);
return NULL;
}
if (!stream->uh)
{
LSQ_INFO("%s: headers unavailable (already fetched?)", __func__);
LSQ_INFO("headers unavailable (already fetched?)");
return NULL;
}
@ -5447,7 +5447,7 @@ lsquic_stream_push_promise (struct lsquic_stream *stream,
#ifdef FIU_ENABLE
if (fiu_fail("stream/fail_initial_pp_write"))
{
LSQ_NOTICE("%s: failed to write push promise (fiu)", __func__);
LSQ_NOTICE("failed to write push promise (fiu)");
nw = -1;
}
else
@ -5528,7 +5528,7 @@ lsquic_stream_set_http_prio (struct lsquic_stream *stream,
{
if (ehp->urgency > LSQUIC_MAX_HTTP_URGENCY)
{
LSQ_INFO("%s: invalid urgency: %hhu", __func__, ehp->urgency);
LSQ_INFO("invalid urgency: %hhu", ehp->urgency);
return -1;
}
stream->sm_priority = ehp->urgency;