Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

improved debugs by printing function name #462

Open
wants to merge 1 commit into
base: master
Choose a base branch
from
Open

improved debugs by printing function name #462

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
1 commit
Select commit
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
8 changes: 4 additions & 4 deletions src/liblsquic/lsquic_bbr.c
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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);
}
Expand Down Expand Up @@ -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)
Expand Down
12 changes: 6 additions & 6 deletions src/liblsquic/lsquic_cubic.c
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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;
}

Expand All @@ -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");
}

Expand Down Expand Up @@ -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;
}

Expand All @@ -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)
{
Expand All @@ -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;
Expand All @@ -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;
Expand Down
2 changes: 1 addition & 1 deletion src/liblsquic/lsquic_di_nocopy.c
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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:
Expand Down
8 changes: 4 additions & 4 deletions src/liblsquic/lsquic_enc_sess_ietf.c
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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;
}
}
Expand Down Expand Up @@ -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;
}

Expand Down Expand Up @@ -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;
}
}
Expand Down Expand Up @@ -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);
}
Expand Down
12 changes: 6 additions & 6 deletions src/liblsquic/lsquic_engine.c
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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;
Expand Down Expand Up @@ -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;
}

Expand Down Expand Up @@ -1939,7 +1939,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;
}

Expand Down Expand Up @@ -2891,7 +2891,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");
}


Expand Down Expand Up @@ -3005,7 +3005,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;
Expand Down Expand Up @@ -3329,7 +3329,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),
Expand Down
6 changes: 4 additions & 2 deletions src/liblsquic/lsquic_ev_log.h
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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
Expand Down
6 changes: 3 additions & 3 deletions src/liblsquic/lsquic_frame_reader.c
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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; \
} \
Expand Down Expand Up @@ -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);
Expand Down
12 changes: 5 additions & 7 deletions src/liblsquic/lsquic_full_conn.c
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -2950,7 +2950,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;
}

Expand All @@ -2963,8 +2963,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;
}
}
Expand Down Expand Up @@ -3261,7 +3260,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);
Expand Down Expand Up @@ -4364,8 +4363,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)
Expand Down Expand Up @@ -4499,7 +4497,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",
Expand Down
24 changes: 11 additions & 13 deletions src/liblsquic/lsquic_full_conn_ietf.c
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -698,7 +698,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;
}
Expand Down Expand Up @@ -1798,7 +1798,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;
Expand Down Expand Up @@ -3066,7 +3066,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");
}


Expand Down Expand Up @@ -3101,7 +3101,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])
Expand Down Expand Up @@ -4326,13 +4326,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);
Expand Down Expand Up @@ -4902,8 +4902,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)
Expand Down Expand Up @@ -7192,15 +7191,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;
}

Expand Down Expand Up @@ -7344,7 +7342,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;
Expand Down Expand Up @@ -8989,7 +8987,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",
Expand Down
Loading