This change adds a small feature to the tcp logging code. Basically

a connection can now have a separate tag added to the id.

Obtained from:	Lawrence Stewart
Sponsored by:	Netflix Inc
Differential Revision:	https://reviews.freebsd.org/D22866
This commit is contained in:
Randall Stewart 2020-01-06 12:48:06 +00:00
parent a1d7296784
commit a9a08eced6
Notes: svn2git 2020-12-20 02:59:44 +00:00
svn path=/head/; revision=356414
3 changed files with 217 additions and 9 deletions

View File

@ -43,7 +43,7 @@ __FBSDID("$FreeBSD$");
#include <sys/socketvar.h>
#include <sys/sysctl.h>
#include <sys/tree.h>
#include <sys/stats.h>
#include <sys/stats.h> /* Must come after qmath.h and tree.h */
#include <sys/counter.h>
#include <dev/tcp_log/tcp_log_dev.h>
@ -78,6 +78,7 @@ static u_long tcp_log_auto_ratio = 0;
static volatile u_long tcp_log_auto_ratio_cur = 0;
static uint32_t tcp_log_auto_mode = TCP_LOG_STATE_TAIL;
static bool tcp_log_auto_all = false;
static uint32_t tcp_disable_all_bb_logs = 0;
RB_PROTOTYPE_STATIC(tcp_log_id_tree, tcp_log_id_bucket, tlb_rb, tcp_log_id_cmp)
@ -111,6 +112,10 @@ SYSCTL_UMA_CUR(_net_inet_tcp_bb, OID_AUTO, log_id_tcpcb_entries, CTLFLAG_RD,
SYSCTL_U32(_net_inet_tcp_bb, OID_AUTO, log_version, CTLFLAG_RD, &tcp_log_version,
0, "Version of log formats exported");
SYSCTL_U32(_net_inet_tcp_bb, OID_AUTO, disable_all, CTLFLAG_RW,
&tcp_disable_all_bb_logs, TCP_LOG_STATE_HEAD_AUTO,
"Disable all BB logging for all connections");
SYSCTL_ULONG(_net_inet_tcp_bb, OID_AUTO, log_auto_ratio, CTLFLAG_RW,
&tcp_log_auto_ratio, 0, "Do auto capturing for 1 out of N sessions");
@ -156,6 +161,17 @@ SYSCTL_COUNTER_U64(_net_inet_tcp_bb, OID_AUTO, freed, CTLFLAG_RD,
#ifdef INVARIANTS
#define TCPLOG_DEBUG_RINGBUF
#endif
/* Number of requests to consider a PBCID "active". */
#define ACTIVE_REQUEST_COUNT 10
/* Statistic tracking for "active" PBCIDs. */
static counter_u64_t tcp_log_pcb_ids_cur;
static counter_u64_t tcp_log_pcb_ids_tot;
SYSCTL_COUNTER_U64(_net_inet_tcp_bb, OID_AUTO, pcb_ids_cur, CTLFLAG_RD,
&tcp_log_pcb_ids_cur, "Number of pcb IDs allocated in the system");
SYSCTL_COUNTER_U64(_net_inet_tcp_bb, OID_AUTO, pcb_ids_tot, CTLFLAG_RD,
&tcp_log_pcb_ids_tot, "Total number of pcb IDs that have been allocated");
struct tcp_log_mem
{
@ -240,10 +256,14 @@ struct tcp_log_id_bucket
* (struct tcp_log_id_bucket *) and (char *) interchangeably.
*/
char tlb_id[TCP_LOG_ID_LEN];
char tlb_tag[TCP_LOG_TAG_LEN];
RB_ENTRY(tcp_log_id_bucket) tlb_rb;
struct tcp_log_id_head tlb_head;
struct mtx tlb_mtx;
volatile u_int tlb_refcnt;
volatile u_int tlb_reqcnt;
uint32_t tlb_loglimit;
uint8_t tlb_logstate;
};
struct tcp_log_id_node
@ -285,6 +305,7 @@ tcp_log_selectauto(void)
* this session.
*/
if (tcp_log_auto_ratio &&
(tcp_disable_all_bb_logs == 0) &&
(atomic_fetchadd_long(&tcp_log_auto_ratio_cur, 1) %
tcp_log_auto_ratio) == 0)
return (true);
@ -337,6 +358,7 @@ tcp_log_remove_bucket(struct tcp_log_id_bucket *tlb)
#endif
}
TCPID_BUCKET_LOCK_DESTROY(tlb);
counter_u64_add(tcp_log_pcb_ids_cur, (int64_t)-1);
uma_zfree(tcp_log_bucket_zone, tlb);
}
@ -484,6 +506,52 @@ tcp_log_grow_tlb(char *tlb_id, struct tcpcb *tp)
#endif
}
static void
tcp_log_increment_reqcnt(struct tcp_log_id_bucket *tlb)
{
atomic_fetchadd_int(&tlb->tlb_reqcnt, 1);
}
/*
* Associate the specified tag with a particular TCP log ID.
* Called with INPCB locked. Returns with it unlocked.
* Returns 0 on success or EOPNOTSUPP if the connection has no TCP log ID.
*/
int
tcp_log_set_tag(struct tcpcb *tp, char *tag)
{
struct tcp_log_id_bucket *tlb;
int tree_locked;
INP_WLOCK_ASSERT(tp->t_inpcb);
tree_locked = TREE_UNLOCKED;
tlb = tp->t_lib;
if (tlb == NULL) {
INP_WUNLOCK(tp->t_inpcb);
return (EOPNOTSUPP);
}
TCPID_BUCKET_REF(tlb);
INP_WUNLOCK(tp->t_inpcb);
TCPID_BUCKET_LOCK(tlb);
strlcpy(tlb->tlb_tag, tag, TCP_LOG_TAG_LEN);
if (!tcp_log_unref_bucket(tlb, &tree_locked, NULL))
TCPID_BUCKET_UNLOCK(tlb);
if (tree_locked == TREE_WLOCKED) {
TCPID_TREE_WLOCK_ASSERT();
TCPID_TREE_WUNLOCK();
} else if (tree_locked == TREE_RLOCKED) {
TCPID_TREE_RLOCK_ASSERT();
TCPID_TREE_RUNLOCK();
} else
TCPID_TREE_UNLOCK_ASSERT();
return (0);
}
/*
* Set the TCP log ID for a TCPCB.
* Called with INPCB locked. Returns with it unlocked.
@ -509,6 +577,21 @@ tcp_log_set_id(struct tcpcb *tp, char *id)
/* See if the ID is unchanged. */
if ((tp->t_lib != NULL && !strcmp(tp->t_lib->tlb_id, id)) ||
(tp->t_lib == NULL && *id == 0)) {
if (tp->t_lib != NULL) {
tcp_log_increment_reqcnt(tp->t_lib);
if ((tp->t_lib->tlb_logstate) &&
(tp->t_log_state_set == 0)) {
/* Clone in any logging */
tp->t_logstate = tp->t_lib->tlb_logstate;
}
if ((tp->t_lib->tlb_loglimit) &&
(tp->t_log_state_set == 0)) {
/* We also have a limit set */
tp->t_loglimit = tp->t_lib->tlb_loglimit;
}
}
rv = 0;
goto done;
}
@ -677,6 +760,18 @@ tcp_log_set_id(struct tcpcb *tp, char *id)
rv = ENOBUFS;
goto done_noinp;
}
counter_u64_add(tcp_log_pcb_ids_cur, 1);
counter_u64_add(tcp_log_pcb_ids_tot, 1);
if ((tcp_log_auto_all == false) &&
tcp_log_auto_mode &&
tcp_log_selectauto()) {
/* Save off the log state */
tlb->tlb_logstate = tcp_log_auto_mode;
} else
tlb->tlb_logstate = TCP_LOG_STATE_OFF;
tlb->tlb_loglimit = 0;
tlb->tlb_tag[0] = '\0'; /* Default to an empty tag. */
/*
* Copy the ID to the bucket.
@ -699,6 +794,7 @@ tcp_log_set_id(struct tcpcb *tp, char *id)
*/
SLIST_INIT(&tlb->tlb_head);
refcount_init(&tlb->tlb_refcnt, 1);
tlb->tlb_reqcnt = 1;
memset(&tlb->tlb_mtx, 0, sizeof(struct mtx));
TCPID_BUCKET_LOCK_INIT(tlb);
TCPID_BUCKET_LOCK(tlb);
@ -707,6 +803,8 @@ tcp_log_set_id(struct tcpcb *tp, char *id)
#define FREE_NEW_TLB() do { \
TCPID_BUCKET_LOCK_DESTROY(tlb); \
uma_zfree(tcp_log_bucket_zone, tlb); \
counter_u64_add(tcp_log_pcb_ids_cur, (int64_t)-1); \
counter_u64_add(tcp_log_pcb_ids_tot, (int64_t)-1); \
bucket_locked = false; \
tlb = NULL; \
} while (0)
@ -762,6 +860,9 @@ tcp_log_set_id(struct tcpcb *tp, char *id)
/* Take a reference on the bucket. */
TCPID_BUCKET_REF(tlb);
/* Record the request. */
tcp_log_increment_reqcnt(tlb);
}
tcp_log_grow_tlb(tlb->tlb_id, tp);
@ -770,6 +871,16 @@ tcp_log_set_id(struct tcpcb *tp, char *id)
SLIST_INSERT_HEAD(&tlb->tlb_head, tln, tln_list);
tp->t_lib = tlb;
tp->t_lin = tln;
if (tp->t_lib->tlb_logstate) {
/* Clone in any logging */
tp->t_logstate = tp->t_lib->tlb_logstate;
}
if (tp->t_lib->tlb_loglimit) {
/* The loglimit too */
tp->t_loglimit = tp->t_lib->tlb_loglimit;
}
tln = NULL;
}
@ -822,6 +933,52 @@ tcp_log_get_id(struct tcpcb *tp, char *buf)
return (len);
}
/*
* Get the tag associated with the TCPCB's log ID.
* Called with INPCB locked. Returns with it unlocked.
* 'buf' must point to a buffer that is at least TCP_LOG_TAG_LEN bytes long.
* Returns number of bytes copied.
*/
size_t
tcp_log_get_tag(struct tcpcb *tp, char *buf)
{
struct tcp_log_id_bucket *tlb;
size_t len;
int tree_locked;
INP_WLOCK_ASSERT(tp->t_inpcb);
tree_locked = TREE_UNLOCKED;
tlb = tp->t_lib;
if (tlb != NULL) {
TCPID_BUCKET_REF(tlb);
INP_WUNLOCK(tp->t_inpcb);
TCPID_BUCKET_LOCK(tlb);
len = strlcpy(buf, tlb->tlb_tag, TCP_LOG_TAG_LEN);
KASSERT(len < TCP_LOG_TAG_LEN,
("%s:%d: tp->t_lib->tlb_tag too long (%zu)",
__func__, __LINE__, len));
if (!tcp_log_unref_bucket(tlb, &tree_locked, NULL))
TCPID_BUCKET_UNLOCK(tlb);
if (tree_locked == TREE_WLOCKED) {
TCPID_TREE_WLOCK_ASSERT();
TCPID_TREE_WUNLOCK();
} else if (tree_locked == TREE_RLOCKED) {
TCPID_TREE_RLOCK_ASSERT();
TCPID_TREE_RUNLOCK();
} else
TCPID_TREE_UNLOCK_ASSERT();
} else {
INP_WUNLOCK(tp->t_inpcb);
*buf = '\0';
len = 0;
}
return (len);
}
/*
* Get number of connections with the same log ID.
* Log ID is taken from given TCPCB.
@ -1005,6 +1162,8 @@ tcp_log_init(void)
tcp_log_que_read = counter_u64_alloc(M_WAITOK);
tcp_log_que_freed = counter_u64_alloc(M_WAITOK);
#endif
tcp_log_pcb_ids_cur = counter_u64_alloc(M_WAITOK);
tcp_log_pcb_ids_tot = counter_u64_alloc(M_WAITOK);
rw_init_flags(&tcp_id_tree_lock, "TCP ID tree", RW_NEW);
mtx_init(&tcp_log_expireq_mtx, "TCP log expireq", NULL, MTX_DEF);
@ -1023,7 +1182,10 @@ tcp_log_tcpcbinit(struct tcpcb *tp)
* If we are doing auto-capturing, figure out whether we will capture
* this session.
*/
if (tcp_log_selectauto()) {
tp->t_loglimit = tcp_log_session_limit;
if ((tcp_log_auto_all == true) &&
tcp_log_auto_mode &&
tcp_log_selectauto()) {
tp->t_logstate = tcp_log_auto_mode;
tp->t_flags2 |= TF2_LOG_AUTO;
}
@ -1162,6 +1324,8 @@ tcp_log_tcpcbfini(struct tcpcb *tp)
INP_WLOCK_ASSERT(tp->t_inpcb);
TCP_LOG_EVENT(tp, NULL, NULL, NULL, TCP_LOG_CONNEND, 0, 0, NULL, false);
/*
* If we were gathering packets to be automatically dumped, try to do
* it now. If this succeeds, the log information in the TCPCB will be
@ -1327,6 +1491,25 @@ tcp_log_tcpcbfini(struct tcpcb *tp)
tp->t_logstate = TCP_LOG_STATE_OFF;
}
static void
tcp_log_purge_tp_logbuf(struct tcpcb *tp)
{
struct tcp_log_mem *log_entry;
struct inpcb *inp;
inp = tp->t_inpcb;
INP_WLOCK_ASSERT(inp);
if (tp->t_lognum == 0)
return;
while ((log_entry = STAILQ_FIRST(&tp->t_logs)) != NULL)
tcp_log_remove_log_head(tp, log_entry);
KASSERT(tp->t_lognum == 0,
("%s: After freeing entries, tp->t_lognum=%d (expected 0)",
__func__, tp->t_lognum));
tp->t_logstate = TCP_LOG_STATE_OFF;
}
/*
* This logs an event for a TCP socket. Normally, this is called via
* TCP_LOG_EVENT or TCP_LOG_EVENT_VERBOSE. See the documentation for
@ -1350,7 +1533,17 @@ tcp_log_event_(struct tcpcb *tp, struct tcphdr *th, struct sockbuf *rxbuf,
__func__, func, line));
INP_WLOCK_ASSERT(tp->t_inpcb);
if (tcp_disable_all_bb_logs) {
/*
* The global shutdown logging
* switch has been thrown. Call
* the purge function that frees
* purges out the logs and
* turns off logging.
*/
tcp_log_purge_tp_logbuf(tp);
return (NULL);
}
KASSERT(tp->t_logstate == TCP_LOG_STATE_HEAD ||
tp->t_logstate == TCP_LOG_STATE_TAIL ||
tp->t_logstate == TCP_LOG_STATE_CONTINUAL ||
@ -1371,7 +1564,7 @@ tcp_log_event_(struct tcpcb *tp, struct tcphdr *th, struct sockbuf *rxbuf,
* here.
*/
retry:
if (tp->t_lognum < tcp_log_session_limit) {
if (tp->t_lognum < tp->t_loglimit) {
if ((log_entry = uma_zalloc(tcp_log_zone, M_NOWAIT)) != NULL)
tp->t_lognum++;
} else
@ -1574,7 +1767,10 @@ tcp_log_state_change(struct tcpcb *tp, int state)
default:
return (EINVAL);
}
if (tcp_disable_all_bb_logs) {
/* We are prohibited from doing any logs */
tp->t_logstate = TCP_LOG_STATE_OFF;
}
tp->t_flags2 &= ~(TF2_LOG_AUTO);
return (0);
@ -1934,6 +2130,7 @@ tcp_log_expandlogbuf(struct tcp_log_dev_queue *param)
hdr->tlh_af = entry->tldl_af;
getboottime(&hdr->tlh_offset);
strlcpy(hdr->tlh_id, entry->tldl_id, TCP_LOG_ID_LEN);
strlcpy(hdr->tlh_tag, entry->tldl_tag, TCP_LOG_TAG_LEN);
strlcpy(hdr->tlh_reason, entry->tldl_reason, TCP_LOG_REASON_LEN);
return ((struct tcp_log_common_header *)hdr);
}
@ -2026,10 +2223,13 @@ tcp_log_dump_tp_logbuf(struct tcpcb *tp, char *reason, int how, bool force)
}
/* Fill in the unique parts of the queue entry. */
if (tp->t_lib != NULL)
if (tp->t_lib != NULL) {
strlcpy(entry->tldl_id, tp->t_lib->tlb_id, TCP_LOG_ID_LEN);
else
strlcpy(entry->tldl_tag, tp->t_lib->tlb_tag, TCP_LOG_TAG_LEN);
} else {
strlcpy(entry->tldl_id, "UNKNOWN", TCP_LOG_ID_LEN);
strlcpy(entry->tldl_tag, "UNKNOWN", TCP_LOG_TAG_LEN);
}
if (reason != NULL)
strlcpy(entry->tldl_reason, reason, TCP_LOG_REASON_LEN);
else
@ -2119,6 +2319,7 @@ tcp_log_dump_node_logbuf(struct tcp_log_id_node *tln, char *reason, int how)
/* Fill in the unique parts of the queue entry. */
strlcpy(entry->tldl_id, tlb->tlb_id, TCP_LOG_ID_LEN);
strlcpy(entry->tldl_tag, tlb->tlb_tag, TCP_LOG_TAG_LEN);
if (reason != NULL)
strlcpy(entry->tldl_reason, reason, TCP_LOG_REASON_LEN);
else

View File

@ -31,7 +31,8 @@
#define __tcp_log_buf_h__
#define TCP_LOG_REASON_LEN 32
#define TCP_LOG_BUF_VER (6)
#define TCP_LOG_TAG_LEN 32
#define TCP_LOG_BUF_VER (7)
/*
* Because the (struct tcp_log_buffer) includes 8-byte uint64_t's, it requires
@ -263,6 +264,7 @@ struct tcp_log_header {
struct timeval tlh_offset; /* Uptime -> UTC offset */
char tlh_id[TCP_LOG_ID_LEN];
char tlh_reason[TCP_LOG_REASON_LEN];
char tlh_tag[TCP_LOG_TAG_LEN];
uint8_t tlh_af;
uint8_t _pad[7];
} ALIGN_TCP_LOG;
@ -272,6 +274,7 @@ struct tcp_log_dev_log_queue {
struct tcp_log_dev_queue tldl_common;
char tldl_id[TCP_LOG_ID_LEN];
char tldl_reason[TCP_LOG_REASON_LEN];
char tldl_tag[TCP_LOG_TAG_LEN];
struct in_endpoints tldl_ie;
struct tcp_log_stailq tldl_entries;
int tldl_count;
@ -349,10 +352,12 @@ struct tcp_log_buffer *tcp_log_event_(struct tcpcb *tp, struct tcphdr *th, struc
union tcp_log_stackspecific *stackinfo, int th_hostorder,
const char *output_caller, const char *func, int line, const struct timeval *tv);
size_t tcp_log_get_id(struct tcpcb *tp, char *buf);
size_t tcp_log_get_tag(struct tcpcb *tp, char *buf);
u_int tcp_log_get_id_cnt(struct tcpcb *tp);
int tcp_log_getlogbuf(struct sockopt *sopt, struct tcpcb *tp);
void tcp_log_init(void);
int tcp_log_set_id(struct tcpcb *tp, char *id);
int tcp_log_set_tag(struct tcpcb *tp, char *tag);
int tcp_log_state_change(struct tcpcb *tp, int state);
void tcp_log_tcpcbinit(struct tcpcb *tp);
void tcp_log_tcpcbfini(struct tcpcb *tp);

View File

@ -103,7 +103,8 @@ struct tcpcb {
t_idle_reduce : 1,
t_delayed_ack: 7, /* Delayed ack variable */
t_fin_is_rst: 1, /* Are fin's treated as resets */
bits_spare : 3;
t_log_state_set: 1,
bits_spare : 2;
u_int t_flags;
tcp_seq snd_una; /* sent but unacknowledged */
tcp_seq snd_max; /* highest sequence number sent;
@ -206,6 +207,7 @@ struct tcpcb {
u_int t_keepcnt; /* number of keepalives before close */
int t_dupacks; /* consecutive dup acks recd */
int t_lognum; /* Number of log entries */
int t_loglimit; /* Maximum number of log entries */
struct tcp_log_stailq t_logs; /* Log buffer */
struct tcp_log_id_node *t_lin;
struct tcp_log_id_bucket *t_lib;