[tcp] improve logging in TCPlp (#7379)

* Avoid printf, and omit newline at end of tcplp_sys_log calls
* Add new tcplp_sys_panic call to use for assertion failures
* Fix code in "#ifdef INSTRUMENT_TCP" so that it can be used
This commit is contained in:
Sam Kumar
2022-01-31 14:32:36 -08:00
committed by GitHub
parent 9e0bf6a263
commit 216b40e4bf
12 changed files with 64 additions and 45 deletions
+1 -1
View File
@@ -190,7 +190,7 @@ newreno_cong_signal(struct cc_var *ccv, uint32_t type)
/* Catch algos which mistakenly leak private signal types. */
KASSERT((type & CC_SIGPRIVMASK) == 0,
("%s: congestion signal type 0x%08x is private\n", __func__, (unsigned int) type));
("%s: congestion signal type 0x%08x is private", __func__, (unsigned int) type));
win = max(CCV(ccv, snd_cwnd) / 2 / CCV(ccv, t_maxseg), 2) *
CCV(ccv, t_maxseg);
+1 -1
View File
@@ -45,7 +45,7 @@
#define __func__ "BSD TCP function"
#define KASSERT(COND, MSG) if (!(COND)) tcplp_sys_log MSG
#define KASSERT(COND, MSG) if (!(COND)) tcplp_sys_panic MSG
typedef uint32_t tcp_seq;
+22 -22
View File
@@ -213,7 +213,7 @@ cc_conn_init(struct tcpcb *tp)
/* samkumar: print statement for debugging. Resurrect with DEBUG macro? */
#ifdef INSTRUMENT_TCP
printf("TCP CC_INIT %u %d %d\n", (unsigned int) get_micros(), (int) tp->snd_cwnd, (int) tp->snd_ssthresh);
tcplp_sys_log("TCP CC_INIT %u %d %d", (unsigned int) tcplp_sys_get_millis(), (int) tp->snd_cwnd, (int) tp->snd_ssthresh);
#endif
}
@@ -255,7 +255,7 @@ cc_cong_signal(struct tcpcb *tp, struct tcphdr *th, uint32_t type)
tcplp_timeoutRexmitCnt++;
#endif
#ifdef INSTRUMENT_TCP
printf("TCP CC_RTO %u %d %d\n", (unsigned int) get_micros(), (int) tp->snd_cwnd, (int) tp->snd_ssthresh);
tcplp_sys_log("TCP CC_RTO %u %d %d", (unsigned int) tcplp_sys_get_millis(), (int) tp->snd_cwnd, (int) tp->snd_ssthresh);
#endif
break;
case CC_RTO_ERR:
@@ -271,7 +271,7 @@ cc_cong_signal(struct tcpcb *tp, struct tcphdr *th, uint32_t type)
tp->t_flags &= ~TF_PREVVALID;
tp->t_badrxtwin = 0;
#ifdef INSTRUMENT_TCP
printf("TCP CC_RTO_ERR %u %d %d\n", (unsigned int) get_micros(), (int) tp->snd_cwnd, (int) tp->snd_ssthresh);
tcplp_sys_log("TCP CC_RTO_ERR %u %d %d", (unsigned int) tcplp_sys_get_millis(), (int) tp->snd_cwnd, (int) tp->snd_ssthresh);
#endif
break;
}
@@ -664,7 +664,7 @@ tcp_input(struct ip6_hdr* ip6, struct tcphdr* th, otMessage* msg, struct tcpcb*
* put "<addrs go here>" where the address string would go.
*/
tcplp_sys_log("%s; %s: Listen socket: "
"SYN is missing, segment ignored\n",
"SYN is missing, segment ignored",
"<addrs go here>", __func__);
goto dropunlock;
}
@@ -674,7 +674,7 @@ tcp_input(struct ip6_hdr* ip6, struct tcphdr* th, otMessage* msg, struct tcpcb*
if (thflags & TH_ACK) {
/* samkumar: See above comment regarding tcp_log_addrs. */
tcplp_sys_log("%s; %s: Listen socket: "
"SYN|ACK invalid, segment rejected\n",
"SYN|ACK invalid, segment rejected",
"<addrs go here>", __func__);
/* samkumar: Removed call to syncache_badack(&inc); */
rstreason = BANDLIM_RST_OPENPORT;
@@ -695,7 +695,7 @@ tcp_input(struct ip6_hdr* ip6, struct tcphdr* th, otMessage* msg, struct tcpcb*
/* samkumar: See above comment regarding tcp_log_addrs. */
tcplp_sys_log("%s; %s: Listen socket: "
"SYN|FIN segment ignored (based on "
"sysctl setting)\n", "<addrs go here>", __func__);
"sysctl setting)", "<addrs go here>", __func__);
goto dropunlock;
}
/*
@@ -745,7 +745,7 @@ tcp_input(struct ip6_hdr* ip6, struct tcphdr* th, otMessage* msg, struct tcpcb*
/* samkumar: See above comment regarding tcp_log_addrs. */
tcplp_sys_log("%s; %s: Listen socket: "
"Connection attempt to/from self "
"ignored\n", "<addrs go here>", __func__);
"ignored", "<addrs go here>", __func__);
goto dropunlock;
}
if (IN6_IS_ADDR_MULTICAST(&ip6->ip6_dst) ||
@@ -753,7 +753,7 @@ tcp_input(struct ip6_hdr* ip6, struct tcphdr* th, otMessage* msg, struct tcpcb*
/* samkumar: See above comment regarding tcp_log_addrs. */
tcplp_sys_log("%s; %s: Listen socket: "
"Connection attempt from/to multicast "
"address ignored\n", "<addrs go here>", __func__);
"address ignored", "<addrs go here>", __func__);
goto dropunlock;
}
@@ -1052,12 +1052,12 @@ tcp_do_segment(struct ip6_hdr* ip6, struct tcphdr *th, otMessage* msg,
if ((tp->t_flags & TF_RCVD_TSTMP) && !(to.to_flags & TOF_TS)) {
/* samkumar: See above comment regarding tcp_log_addrs. */
tcplp_sys_log("%s; %s: Timestamp missing, "
"no action\n", "<addrs go here>", __func__);
"no action", "<addrs go here>", __func__);
}
if (!(tp->t_flags & TF_RCVD_TSTMP) && (to.to_flags & TOF_TS)) {
/* samkumar: See above comment regarding tcp_log_addrs. */
tcplp_sys_log("%s; %s: Timestamp not expected, "
"no action\n", "<addrs go here>", __func__);
"no action", "<addrs go here>", __func__);
}
/*
@@ -1633,7 +1633,7 @@ tcp_do_segment(struct ip6_hdr* ip6, struct tcphdr *th, otMessage* msg,
* for legacy code, which we don't really care about in TCPlp).
*/
/* Send challenge ACK. */
tcplp_sys_log("Sending challenge ACK\n");
tcplp_sys_log("Sending challenge ACK");
tcp_respond(tp, tp->instance, ip6, th, tp->rcv_nxt, tp->snd_nxt, TH_ACK);
tp->last_ack_sent = tp->rcv_nxt;
goto drop;
@@ -1805,7 +1805,7 @@ tcp_do_segment(struct ip6_hdr* ip6, struct tcphdr *th, otMessage* msg,
goto drop;
}
tcplp_sys_log("Processing ACK\n");
tcplp_sys_log("Processing ACK");
/*
* Ack processing.
@@ -1967,7 +1967,7 @@ tcp_do_segment(struct ip6_hdr* ip6, struct tcphdr *th, otMessage* msg,
} else
tp->snd_cwnd += tp->t_maxseg;
#ifdef INSTRUMENT_TCP
printf("TCP DUPACK\n");
tcplp_sys_log("TCP DUPACK");
#endif
(void) tcp_output(tp);
goto drop;
@@ -2000,7 +2000,7 @@ tcp_do_segment(struct ip6_hdr* ip6, struct tcphdr *th, otMessage* msg,
tp->t_rtttime = 0;
#ifdef INSTRUMENT_TCP
printf("TCP DUPACK_THRESH\n");
tcplp_sys_log("TCP DUPACK_THRESH");
#endif
if (tp->t_flags & TF_SACK_PERMIT) {
tp->sack_newdata = tp->snd_nxt;
@@ -2016,7 +2016,7 @@ tcp_do_segment(struct ip6_hdr* ip6, struct tcphdr *th, otMessage* msg,
tp->t_maxseg *
(tp->t_dupacks - tp->snd_limited);
#ifdef INSTRUMENT_TCP
printf("TCP SET_cwnd %d\n", (int) tp->snd_cwnd);
tcplp_sys_log("TCP SET_cwnd %d", (int) tp->snd_cwnd);
#endif
if (SEQ_GT(onxt, tp->snd_nxt))
tp->snd_nxt = onxt;
@@ -2041,7 +2041,7 @@ tcp_do_segment(struct ip6_hdr* ip6, struct tcphdr *th, otMessage* msg,
oldsndmax = tp->snd_max;
#ifdef INSTRUMENT_TCP
printf("TCP LIM_TRANS\n");
tcplp_sys_log("TCP LIM_TRANS");
#endif
KASSERT(tp->t_dupacks == 1 ||
@@ -2080,7 +2080,7 @@ tcp_do_segment(struct ip6_hdr* ip6, struct tcphdr *th, otMessage* msg,
++tp->snd_limited;
tp->snd_cwnd = oldcwnd;
#ifdef INSTRUMENT_TCP
printf("TCP RESET_cwnd %d\n", (int) tp->snd_cwnd);
tcplp_sys_log("TCP RESET_cwnd %d", (int) tp->snd_cwnd);
#endif
goto drop;
}
@@ -2132,7 +2132,7 @@ tcp_do_segment(struct ip6_hdr* ip6, struct tcphdr *th, otMessage* msg,
process_ACK:
acked = BYTES_THIS_ACK(tp, th);
tcplp_sys_log("Bytes acked: %d\n", acked);
tcplp_sys_log("Bytes acked: %d", acked);
/*
* If we just performed our first retransmit, and the ACK
* arrives within our recovery window, then it was a mistake
@@ -2486,7 +2486,7 @@ step6:
* that the connection is closing.
*/
if (thflags & TH_FIN) {
tcplp_sys_log("FIN Processing start\n");
tcplp_sys_log("FIN Processing start");
if (TCPS_HAVERCVDFIN(tp->t_state) == 0) {
/* samkumar: replace socantrcvmore with tpcantrcvmore */
tpcantrcvmore(tp);
@@ -2759,7 +2759,7 @@ tcp_xmit_timer(struct tcpcb *tp, int rtt)
max(tp->t_rttmin, rtt + 2), TCPTV_REXMTMAX);
#ifdef INSTRUMENT_TCP
printf("TCP timer %u %d %d %d\n", (unsigned int) get_micros(), rtt, (int) tp->t_srtt, (int) tp->t_rttvar);
tcplp_sys_log("TCP timer %u %d %d %d", (unsigned int) tcplp_sys_get_millis(), rtt, (int) tp->t_srtt, (int) tp->t_rttvar);
#endif
@@ -3072,7 +3072,7 @@ tcp_newreno_partial_ack(struct tcpcb *tp, struct tcphdr *th)
tp->snd_cwnd = tp->t_maxseg + BYTES_THIS_ACK(tp, th);
tp->t_flags |= TF_ACKNOW;
#ifdef INSTRUMENT_TCP
printf("TCP Partial_ACK\n");
tcplp_sys_log("TCP Partial_ACK");
#endif
(void) tcp_output(tp);
tp->snd_cwnd = ocwnd;
@@ -3088,6 +3088,6 @@ tcp_newreno_partial_ack(struct tcpcb *tp, struct tcphdr *th)
tp->snd_cwnd = 0;
tp->snd_cwnd += tp->t_maxseg;
#ifdef INSTRUMENT_TCP
printf("TCP Partial_ACK_final %d\n", (int) tp->snd_cwnd);
tcplp_sys_log("TCP Partial_ACK_final %d", (int) tp->snd_cwnd);
#endif
}
+5 -5
View File
@@ -81,7 +81,7 @@ tcp_setpersist(struct tcpcb *tp)
tp->t_flags &= ~TF_PREVVALID;
if (tcp_timer_active(tp, TT_REXMT))
printf("PANIC: tcp_setpersist: retransmit pending\n");
tcplp_sys_panic("PANIC: tcp_setpersist: retransmit pending");
/*
* Start/restart persistance timer.
*/
@@ -142,7 +142,7 @@ tcp_output(struct tcpcb *tp)
}
/* samkumar: This would be printed once per _window_ that is transmitted. */
#ifdef INSTRUMENT_TCP
printf("TCP output %u %d %d\n", (unsigned int) get_micros(), (int) tp->snd_wnd, (int) tp->snd_cwnd);
tcplp_sys_log("TCP output %u %d %d", (unsigned int) tcplp_sys_get_millis(), (int) tp->snd_wnd, (int) tp->snd_cwnd);
#endif
again:
@@ -898,7 +898,7 @@ send:
otLinkedBuffer* curr;
int rv = lbuf_getrange(&tp->sendbuf, off, len, &start, &start_offset, &end, &end_offset);
size_t message_offset = otMessageGetOffset(message) + sizeof(struct tcphdr) + optlen;
KASSERT(rv == 0, ("Reading send buffer out of range!\n"));
KASSERT(rv == 0, ("Reading send buffer out of range!"));
for (curr = start; curr != end->mNext; curr = curr->mNext) {
const uint8_t* data_to_copy = curr->mData;
size_t length_to_copy = curr->mLength;
@@ -1258,7 +1258,7 @@ timer:
tcp_timer_activate(tp, TT_REXMT, tp->t_rxtcur);
tp->snd_cwnd = tp->t_maxseg;
#ifdef INSTRUMENT_TCP
printf("TCP ALLOCFAIL %u %d\n", (unsigned int) get_micros(), (int) tp->snd_cwnd);
tcplp_sys_log("TCP ALLOCFAIL %u %d", (unsigned int) tcplp_sys_get_millis(), (int) tp->snd_cwnd);
#endif
return (0);
case EMSGSIZE:
@@ -1454,7 +1454,7 @@ tcp_addoptions(struct tcpopt *to, uint8_t *optp)
break;
}
default:
printf("PANIC: %s: unknown TCP option type", __func__);
tcplp_sys_panic("PANIC: %s: unknown TCP option type", __func__);
break;
}
}
+4 -4
View File
@@ -71,7 +71,7 @@ tcp_reass(struct tcpcb* tp, struct tcphdr* th, int* tlenp, otMessage* data, off_
tlen = *tlenp;
/* Insert the new segment queue entry into place. */
KASSERT(SEQ_GEQ(th->th_seq, tp->rcv_nxt), ("Adding past segment to the reassembly queue\n"));
KASSERT(SEQ_GEQ(th->th_seq, tp->rcv_nxt), ("Adding past segment to the reassembly queue"));
offset = (size_t) (th->th_seq - tp->rcv_nxt);
if (cbuf_reass_count_set(&tp->recvbuf, (size_t) offset, tp->reassbmp, tlen) >= (size_t) tlen) {
@@ -83,7 +83,7 @@ tcp_reass(struct tcpcb* tp, struct tcphdr* th, int* tlenp, otMessage* data, off_
if ((th->th_flags & TH_FIN) && (tp->reass_fin_index == -1)) {
tp->reass_fin_index = (int16_t) (start_index + tlen);
}
KASSERT(written == tlen, ("Reassembly write out of bounds: tried to write %d, but wrote %d\n", tlen, (int) written));
KASSERT(written == tlen, ("Reassembly write out of bounds: tried to write %d, but wrote %d", tlen, (int) written));
present:
/*
@@ -100,7 +100,7 @@ present:
flags = TH_FIN;
}
merged = cbuf_reass_merge(&tp->recvbuf, mergeable, tp->reassbmp);
KASSERT(merged == mergeable, ("Reassembly merge out of bounds: tried to merge %d, but merged %d\n", (int) mergeable, (int) merged));
KASSERT(merged == mergeable, ("Reassembly merge out of bounds: tried to merge %d, but merged %d", (int) mergeable, (int) merged));
if (tpiscantrcv(tp)) {
cbuf_pop(&tp->recvbuf, merged); // So no data really enters the buffer
} else if (usedbefore == 0 && merged > 0) {
@@ -109,7 +109,7 @@ present:
} else {
/* If there is data in the buffer AND we can't receive more, then that must be because we received a FIN,
but the user hasn't yet emptied the buffer of its contents. */
KASSERT (tp->reass_fin_index == -2, ("Can't receive more, and data in buffer, but haven't received a FIN\n"));
KASSERT (tp->reass_fin_index == -2, ("Can't receive more, and data in buffer, but haven't received a FIN"));
}
tp->rcv_nxt += mergeable;
+1 -1
View File
@@ -119,7 +119,7 @@ struct sackhole* sackhole_alloc(struct tcpcb* tp) {
void sackhole_free(struct tcpcb* tp, struct sackhole* tofree) {
size_t freeindex = (size_t) (tofree - &tp->sackhole_pool[0]);
KASSERT(tofree == &tp->sackhole_pool[freeindex], ("sackhole pool unaligned\n"));
KASSERT(tofree == &tp->sackhole_pool[freeindex], ("sackhole pool unaligned"));
bmp_clrrange(tp->sackhole_bmp, freeindex, 1);
}
+1 -1
View File
@@ -79,7 +79,7 @@ tcp_state_change(struct tcpcb *tp, int newstate)
int pstate = tp->t_state;
#endif
#endif
tcplp_sys_log("Socket %p: %s --> %s\n", tp, tcpstates[tp->t_state], tcpstates[newstate]);
tcplp_sys_log("Socket %p: %s --> %s", tp, tcpstates[tp->t_state], tcpstates[newstate]);
tp->t_state = newstate;
// samkumar: may need to do other actions too, so call into the host
+8 -9
View File
@@ -67,7 +67,7 @@ int
tcp_timer_delack(struct tcpcb* tp)
{
/* samkumar: I added this, to replace the code I removed below. */
KASSERT(tpistimeractive(tp, TT_DELACK), ("Delack timer running, but unmarked\n"));
KASSERT(tpistimeractive(tp, TT_DELACK), ("Delack timer running, but unmarked"));
tpcleartimeractive(tp, TT_DELACK);
/*
@@ -91,7 +91,7 @@ tcp_timer_keep(struct tcpcb* tp)
struct tcptemp t_template;
/* samkumar: I added this, to replace the code I removed below. */
KASSERT(tpistimeractive(tp, TT_KEEP), ("Keep timer running, but unmarked\n"));
KASSERT(tpistimeractive(tp, TT_KEEP), ("Keep timer running, but unmarked"));
tpcleartimeractive(tp, TT_KEEP);
/*
@@ -175,7 +175,7 @@ tcp_timer_persist(struct tcpcb* tp)
int dropped = 0;
/* samkumar: I added this, to replace the code I removed below. */
KASSERT(tpistimeractive(tp, TT_PERSIST), ("Persist timer running, but unmarked\n"));
KASSERT(tpistimeractive(tp, TT_PERSIST), ("Persist timer running, but unmarked"));
tpcleartimeractive(tp, TT_PERSIST); // mark that this timer is no longer active
/*
@@ -223,7 +223,7 @@ tcp_timer_persist(struct tcpcb* tp)
tcp_setpersist(tp);
tp->t_flags |= TF_FORCEDATA;
tcplp_sys_log("Persist output: %zu bytes in sendbuf\n", lbuf_used_space(&tp->sendbuf));
tcplp_sys_log("Persist output: %zu bytes in sendbuf", lbuf_used_space(&tp->sendbuf));
(void) tcp_output(tp);
tp->t_flags &= ~TF_FORCEDATA;
@@ -243,7 +243,7 @@ tcp_timer_2msl(struct tcpcb* tp)
int dropped = 0;
/* samkumar: I added this, to replace the code I removed below. */
KASSERT(tpistimeractive(tp, TT_2MSL), ("2MSL timer running, but unmarked\n"));
KASSERT(tpistimeractive(tp, TT_2MSL), ("2MSL timer running, but unmarked"));
tpcleartimeractive(tp, TT_2MSL);
/*
@@ -335,7 +335,7 @@ tcp_timer_rexmt(struct tcpcb *tp)
int dropped = 0;
/* samkumar: I added this, to replace the code I removed below. */
KASSERT(tpistimeractive(tp, TT_REXMT), ("Rexmt timer running, but unmarked\n"));
KASSERT(tpistimeractive(tp, TT_REXMT), ("Rexmt timer running, but unmarked"));
tpcleartimeractive(tp, TT_REXMT);
/*
@@ -354,7 +354,7 @@ tcp_timer_rexmt(struct tcpcb *tp)
* been acked within retransmit interval. Back off
* to a longer retransmit interval and retransmit one segment.
*/
tcplp_sys_log("rxtshift is %d\n", (int) tp->t_rxtshift);
tcplp_sys_log("rxtshift is %d", (int) tp->t_rxtshift);
if (++tp->t_rxtshift > TCP_MAXRXTSHIFT) {
tp->t_rxtshift = TCP_MAXRXTSHIFT;
@@ -477,8 +477,7 @@ tcp_timer_activate(struct tcpcb *tp, uint32_t timer_type, uint32_t delta) {
if (delta) {
tpmarktimeractive(tp, timer_type);
if (tpistimeractive(tp, TT_REXMT) && tpistimeractive(tp, TT_PERSIST)) {
char* msg = "TCP CRITICAL FAILURE: Retransmit and Persist timers are simultaneously running!\n";
tcplp_sys_log("%s\n", msg);
tcplp_sys_panic("TCP CRITICAL FAILURE: Retransmit and Persist timers are simultaneously running!");
}
tcplp_sys_set_timer(tp, timer_type, (uint32_t) delta);
} else {
+1 -1
View File
@@ -192,7 +192,7 @@ tcp6_usr_connect(struct tcpcb* tp, struct sockaddr_in6* sin6p)
* Is this a significant problem?
*/
if (IN6_IS_ADDR_V4MAPPED(&sin6p->sin6_addr)) {
tcplp_sys_log("V4-Mapped Address!\n");
tcplp_sys_log("V4-Mapped Address!");
/*
* samkumar: There used to be code that woulf handle the case of
+6
View File
@@ -141,6 +141,11 @@ int bmp_isempty(uint8_t* buf, size_t buflen) {
return 1;
}
/*
* This function is unused, but I'm leaving it in the code as a comment in case
* it becomes useful for debugging later on.
*/
#if 0
void bmp_print(uint8_t* buf, size_t buflen) {
size_t i;
for (i = 0; i < buflen; i++) {
@@ -148,3 +153,4 @@ void bmp_print(uint8_t* buf, size_t buflen) {
}
printf("\n");
}
#endif
+1
View File
@@ -76,6 +76,7 @@ bool tcplp_sys_accepted_connection(struct tcpcb_listen* tpl, struct tcpcb* accep
void tcplp_sys_connection_lost(struct tcpcb* tcb, uint8_t errnum);
void tcplp_sys_on_state_change(struct tcpcb* tcb, int newstate);
void tcplp_sys_log(const char* format, ...);
void tcplp_sys_panic(const char* format, ...);
bool tcplp_sys_autobind(otInstance *aInstance, const otSockAddr *aPeer, otSockAddr *aToBind, bool aBindAddress, bool aBindPort);
uint32_t tcplp_sys_generate_isn();