#include "opt_inet.h"
#include "opt_ddb.h"
#include <sys/param.h>
#include <sys/arb.h>
#include <sys/hash.h>
#include <sys/kernel.h>
#include <sys/lock.h>
#include <sys/malloc.h>
#include <sys/mutex.h>
#include <sys/qmath.h>
#include <sys/queue.h>
#include <sys/refcount.h>
#include <sys/rwlock.h>
#include <sys/socket.h>
#include <sys/socketvar.h>
#include <sys/sysctl.h>
#ifdef DDB
#include <sys/time.h>
#endif
#include <sys/tree.h>
#include <sys/stats.h>
#include <sys/counter.h>
#include <dev/tcp_log/tcp_log_dev.h>
#ifdef DDB
#include <ddb/ddb.h>
#endif
#include <net/if.h>
#include <net/if_var.h>
#include <net/vnet.h>
#include <netinet/in.h>
#ifdef DDB
#include <netinet/in_kdtrace.h>
#endif
#include <netinet/in_pcb.h>
#include <netinet/in_var.h>
#include <netinet/tcp_var.h>
#include <netinet/tcp_log_buf.h>
#include <netinet/tcp_seq.h>
#include <netinet/tcp_hpts.h>
#define TCP_LOG_EXPIRE_TIME ((sbintime_t)60 * SBT_1S)
#define TCP_LOG_EXPIRE_INTVL ((sbintime_t)5 * SBT_1S)
bool tcp_log_verbose;
static uma_zone_t tcp_log_id_bucket_zone, tcp_log_id_node_zone, tcp_log_zone;
static int tcp_log_session_limit = TCP_LOG_BUF_DEFAULT_SESSION_LIMIT;
static uint32_t tcp_log_version = TCP_LOG_BUF_VER;
RB_HEAD(tcp_log_id_tree, tcp_log_id_bucket);
static struct tcp_log_id_tree tcp_log_id_head;
static STAILQ_HEAD(, tcp_log_id_node) tcp_log_expireq_head =
STAILQ_HEAD_INITIALIZER(tcp_log_expireq_head);
static struct mtx tcp_log_expireq_mtx;
static struct callout tcp_log_expireq_callout;
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)
SYSCTL_NODE(_net_inet_tcp, OID_AUTO, bb, CTLFLAG_RW | CTLFLAG_MPSAFE, 0,
"TCP Black Box controls");
SYSCTL_NODE(_net_inet_tcp_bb, OID_AUTO, tp, CTLFLAG_RW | CTLFLAG_MPSAFE, 0,
"TCP Black Box Trace Point controls");
SYSCTL_BOOL(_net_inet_tcp_bb, OID_AUTO, log_verbose, CTLFLAG_RW, &tcp_log_verbose,
0, "Force verbose logging for TCP traces");
SYSCTL_INT(_net_inet_tcp_bb, OID_AUTO, log_session_limit,
CTLFLAG_RW, &tcp_log_session_limit, 0,
"Maximum number of events maintained for each TCP session");
uint32_t tcp_trace_point_config = 0;
SYSCTL_U32(_net_inet_tcp_bb_tp, OID_AUTO, number, CTLFLAG_RW,
&tcp_trace_point_config, TCP_LOG_STATE_HEAD_AUTO,
"What is the trace point number to activate (0=none, 0xffffffff = all)?");
uint32_t tcp_trace_point_bb_mode = TCP_LOG_STATE_CONTINUAL;
SYSCTL_U32(_net_inet_tcp_bb_tp, OID_AUTO, bbmode, CTLFLAG_RW,
&tcp_trace_point_bb_mode, TCP_LOG_STATE_HEAD_AUTO,
"What is BB logging mode that is activated?");
int32_t tcp_trace_point_count = 0;
SYSCTL_U32(_net_inet_tcp_bb_tp, OID_AUTO, count, CTLFLAG_RW,
&tcp_trace_point_count, TCP_LOG_STATE_HEAD_AUTO,
"How many connections will have BB logging turned on that hit the tracepoint?");
SYSCTL_UMA_MAX(_net_inet_tcp_bb, OID_AUTO, log_global_limit, CTLFLAG_RW,
&tcp_log_zone, "Maximum number of events maintained for all TCP sessions");
SYSCTL_UMA_CUR(_net_inet_tcp_bb, OID_AUTO, log_global_entries, CTLFLAG_RD,
&tcp_log_zone, "Current number of events maintained for all TCP sessions");
SYSCTL_UMA_MAX(_net_inet_tcp_bb, OID_AUTO, log_id_limit, CTLFLAG_RW,
&tcp_log_id_bucket_zone, "Maximum number of log IDs");
SYSCTL_UMA_CUR(_net_inet_tcp_bb, OID_AUTO, log_id_entries, CTLFLAG_RD,
&tcp_log_id_bucket_zone, "Current number of log IDs");
SYSCTL_UMA_MAX(_net_inet_tcp_bb, OID_AUTO, log_id_tcpcb_limit, CTLFLAG_RW,
&tcp_log_id_node_zone, "Maximum number of tcpcbs with log IDs");
SYSCTL_UMA_CUR(_net_inet_tcp_bb, OID_AUTO, log_id_tcpcb_entries, CTLFLAG_RD,
&tcp_log_id_node_zone, "Current number of tcpcbs with log IDs");
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, 0,
"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");
SYSCTL_U32(_net_inet_tcp_bb, OID_AUTO, log_auto_mode, CTLFLAG_RW,
&tcp_log_auto_mode, 0,
"Logging mode for auto-selected sessions (default is TCP_LOG_STATE_TAIL)");
SYSCTL_BOOL(_net_inet_tcp_bb, OID_AUTO, log_auto_all, CTLFLAG_RW,
&tcp_log_auto_all, 0,
"Auto-select from all sessions (rather than just those with IDs)");
#ifdef TCPLOG_DEBUG_COUNTERS
counter_u64_t tcp_log_queued;
counter_u64_t tcp_log_que_fail1;
counter_u64_t tcp_log_que_fail2;
counter_u64_t tcp_log_que_fail3;
counter_u64_t tcp_log_que_fail4;
counter_u64_t tcp_log_que_fail5;
counter_u64_t tcp_log_que_copyout;
counter_u64_t tcp_log_que_read;
counter_u64_t tcp_log_que_freed;
SYSCTL_COUNTER_U64(_net_inet_tcp_bb, OID_AUTO, queued, CTLFLAG_RD,
&tcp_log_queued, "Number of entries queued");
SYSCTL_COUNTER_U64(_net_inet_tcp_bb, OID_AUTO, fail1, CTLFLAG_RD,
&tcp_log_que_fail1, "Number of entries queued but fail 1");
SYSCTL_COUNTER_U64(_net_inet_tcp_bb, OID_AUTO, fail2, CTLFLAG_RD,
&tcp_log_que_fail2, "Number of entries queued but fail 2");
SYSCTL_COUNTER_U64(_net_inet_tcp_bb, OID_AUTO, fail3, CTLFLAG_RD,
&tcp_log_que_fail3, "Number of entries queued but fail 3");
SYSCTL_COUNTER_U64(_net_inet_tcp_bb, OID_AUTO, fail4, CTLFLAG_RD,
&tcp_log_que_fail4, "Number of entries queued but fail 4");
SYSCTL_COUNTER_U64(_net_inet_tcp_bb, OID_AUTO, fail5, CTLFLAG_RD,
&tcp_log_que_fail5, "Number of entries queued but fail 4");
SYSCTL_COUNTER_U64(_net_inet_tcp_bb, OID_AUTO, copyout, CTLFLAG_RD,
&tcp_log_que_copyout, "Number of entries copied out");
SYSCTL_COUNTER_U64(_net_inet_tcp_bb, OID_AUTO, read, CTLFLAG_RD,
&tcp_log_que_read, "Number of entries read from the queue");
SYSCTL_COUNTER_U64(_net_inet_tcp_bb, OID_AUTO, freed, CTLFLAG_RD,
&tcp_log_que_freed, "Number of entries freed after reading");
#endif
#ifdef INVARIANTS
#define TCPLOG_DEBUG_RINGBUF
#endif
#define ACTIVE_REQUEST_COUNT 10
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
{
STAILQ_ENTRY(tcp_log_mem) tlm_queue;
struct tcp_log_buffer tlm_buf;
struct tcp_log_verbose tlm_v;
#ifdef TCPLOG_DEBUG_RINGBUF
volatile int tlm_refcnt;
#endif
};
static uint8_t zerobuf[76];
static struct rwlock tcp_id_tree_lock;
#define TCPID_TREE_WLOCK() rw_wlock(&tcp_id_tree_lock)
#define TCPID_TREE_RLOCK() rw_rlock(&tcp_id_tree_lock)
#define TCPID_TREE_UPGRADE() rw_try_upgrade(&tcp_id_tree_lock)
#define TCPID_TREE_WUNLOCK() rw_wunlock(&tcp_id_tree_lock)
#define TCPID_TREE_RUNLOCK() rw_runlock(&tcp_id_tree_lock)
#define TCPID_TREE_WLOCK_ASSERT() rw_assert(&tcp_id_tree_lock, RA_WLOCKED)
#define TCPID_TREE_RLOCK_ASSERT() rw_assert(&tcp_id_tree_lock, RA_RLOCKED)
#define TCPID_TREE_UNLOCK_ASSERT() rw_assert(&tcp_id_tree_lock, RA_UNLOCKED)
#define TCPID_BUCKET_LOCK_INIT(tlb) mtx_init(&((tlb)->tlb_mtx), "tcp log id bucket", NULL, MTX_DEF)
#define TCPID_BUCKET_LOCK_DESTROY(tlb) mtx_destroy(&((tlb)->tlb_mtx))
#define TCPID_BUCKET_LOCK(tlb) mtx_lock(&((tlb)->tlb_mtx))
#define TCPID_BUCKET_UNLOCK(tlb) mtx_unlock(&((tlb)->tlb_mtx))
#define TCPID_BUCKET_LOCK_ASSERT(tlb) mtx_assert(&((tlb)->tlb_mtx), MA_OWNED)
#define TCPID_BUCKET_UNLOCK_ASSERT(tlb) mtx_assert(&((tlb)->tlb_mtx), MA_NOTOWNED)
#define TCPID_BUCKET_REF(tlb) refcount_acquire(&((tlb)->tlb_refcnt))
#define TCPID_BUCKET_UNREF(tlb) refcount_release(&((tlb)->tlb_refcnt))
#define TCPLOG_EXPIREQ_LOCK() mtx_lock(&tcp_log_expireq_mtx)
#define TCPLOG_EXPIREQ_UNLOCK() mtx_unlock(&tcp_log_expireq_mtx)
SLIST_HEAD(tcp_log_id_head, tcp_log_id_node);
struct tcp_log_id_bucket
{
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;
int8_t tlb_logstate;
};
struct tcp_log_id_node
{
SLIST_ENTRY(tcp_log_id_node) tln_list;
STAILQ_ENTRY(tcp_log_id_node) tln_expireq;
sbintime_t tln_expiretime;
struct inpcb *tln_inp;
struct tcpcb *tln_tp;
struct tcp_log_id_bucket *tln_bucket;
struct in_endpoints tln_ie;
struct tcp_log_stailq tln_entries;
int tln_count;
volatile int tln_closed;
uint8_t tln_af;
};
enum tree_lock_state {
TREE_UNLOCKED = 0,
TREE_RLOCKED,
TREE_WLOCKED,
};
static __inline bool
tcp_log_selectauto(void)
{
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);
return (false);
}
static __inline int
tcp_log_id_cmp(struct tcp_log_id_bucket *a, struct tcp_log_id_bucket *b)
{
KASSERT(a != NULL, ("tcp_log_id_cmp: argument a is unexpectedly NULL"));
KASSERT(b != NULL, ("tcp_log_id_cmp: argument b is unexpectedly NULL"));
return strncmp(a->tlb_id, b->tlb_id, TCP_LOG_ID_LEN);
}
RB_GENERATE_STATIC(tcp_log_id_tree, tcp_log_id_bucket, tlb_rb, tcp_log_id_cmp)
static __inline void
tcp_log_id_validate_tree_lock(int tree_locked)
{
#ifdef INVARIANTS
switch (tree_locked) {
case TREE_WLOCKED:
TCPID_TREE_WLOCK_ASSERT();
break;
case TREE_RLOCKED:
TCPID_TREE_RLOCK_ASSERT();
break;
case TREE_UNLOCKED:
TCPID_TREE_UNLOCK_ASSERT();
break;
default:
kassert_panic("%s:%d: unknown tree lock state", __func__,
__LINE__);
}
#endif
}
static __inline void
tcp_log_remove_bucket(struct tcp_log_id_bucket *tlb)
{
TCPID_TREE_WLOCK_ASSERT();
KASSERT(SLIST_EMPTY(&tlb->tlb_head),
("%s: Attempt to remove non-empty bucket", __func__));
if (RB_REMOVE(tcp_log_id_tree, &tcp_log_id_head, tlb) == NULL) {
#ifdef INVARIANTS
kassert_panic("%s:%d: error removing element from tree",
__func__, __LINE__);
#endif
}
TCPID_BUCKET_LOCK_DESTROY(tlb);
counter_u64_add(tcp_log_pcb_ids_cur, (int64_t)-1);
uma_zfree(tcp_log_id_bucket_zone, tlb);
}
static bool
tcp_log_unref_bucket(struct tcp_log_id_bucket *tlb, int *tree_locked,
struct inpcb *inp)
{
KASSERT(tlb != NULL, ("%s: called with NULL tlb", __func__));
KASSERT(tree_locked != NULL, ("%s: called with NULL tree_locked",
__func__));
tcp_log_id_validate_tree_lock(*tree_locked);
while (TCPID_BUCKET_UNREF(tlb)) {
if (*tree_locked == TREE_RLOCKED && TCPID_TREE_UPGRADE())
*tree_locked = TREE_WLOCKED;
else if (*tree_locked != TREE_WLOCKED) {
TCPID_BUCKET_REF(tlb);
if (inp != NULL)
INP_WUNLOCK(inp);
TCPID_BUCKET_UNLOCK(tlb);
if (*tree_locked == TREE_RLOCKED)
TCPID_TREE_RUNLOCK();
TCPID_TREE_WLOCK();
*tree_locked = TREE_WLOCKED;
TCPID_BUCKET_LOCK(tlb);
if (inp != NULL)
INP_WLOCK(inp);
continue;
}
tcp_log_remove_bucket(tlb);
return (true);
}
return (false);
}
static bool
tcp_log_remove_id_node(struct inpcb *inp, struct tcpcb *tp,
struct tcp_log_id_bucket *tlb, struct tcp_log_id_node *tln,
int *tree_locked)
{
int orig_tree_locked;
KASSERT(tp != NULL || (tlb != NULL && tln != NULL),
("%s: called with tp=%p, tlb=%p, tln=%p", __func__,
tp, tlb, tln));
KASSERT(tree_locked != NULL, ("%s: called with NULL tree_locked",
__func__));
if (tp != NULL) {
tlb = tp->t_lib;
tln = tp->t_lin;
KASSERT(tlb != NULL, ("%s: unexpectedly NULL tlb", __func__));
KASSERT(tln != NULL, ("%s: unexpectedly NULL tln", __func__));
}
tcp_log_id_validate_tree_lock(*tree_locked);
TCPID_BUCKET_LOCK_ASSERT(tlb);
SLIST_REMOVE(&tlb->tlb_head, tln, tcp_log_id_node, tln_list);
if (tp != NULL) {
tp->t_lib = NULL;
tp->t_lin = NULL;
}
orig_tree_locked = *tree_locked;
if (!tcp_log_unref_bucket(tlb, tree_locked, inp))
TCPID_BUCKET_UNLOCK(tlb);
return (*tree_locked != orig_tree_locked);
}
#define RECHECK_INP_CLEAN(cleanup) do { \
if (inp->inp_flags & INP_DROPPED) { \
rv = ECONNRESET; \
cleanup; \
goto done; \
} \
tp = intotcpcb(inp); \
} while (0)
#define RECHECK_INP() RECHECK_INP_CLEAN()
static void
tcp_log_grow_tlb(char *tlb_id, struct tcpcb *tp)
{
INP_WLOCK_ASSERT(tptoinpcb(tp));
#ifdef STATS
if (V_tcp_perconn_stats_enable == 2 && tp->t_stats == NULL)
(void)tcp_stats_sample_rollthedice(tp, tlb_id, strlen(tlb_id));
#endif
}
static void
tcp_log_increment_reqcnt(struct tcp_log_id_bucket *tlb)
{
atomic_fetchadd_int(&tlb->tlb_reqcnt, 1);
}
int
tcp_log_apply_ratio(struct tcpcb *tp, int ratio)
{
struct tcp_log_id_bucket *tlb;
struct inpcb *inp = tptoinpcb(tp);
uint32_t hash, ratio_hash_thresh;
int rv, tree_locked;
rv = 0;
tree_locked = TREE_UNLOCKED;
tlb = tp->t_lib;
INP_WLOCK_ASSERT(inp);
if (tlb == NULL) {
INP_WUNLOCK(inp);
return (EOPNOTSUPP);
}
if (ratio)
ratio_hash_thresh = max(1, UINT32_MAX / ratio);
else
ratio_hash_thresh = 0;
TCPID_BUCKET_REF(tlb);
INP_WUNLOCK(inp);
TCPID_BUCKET_LOCK(tlb);
hash = hash32_buf(tlb->tlb_id, strlen(tlb->tlb_id), 0);
if (hash > ratio_hash_thresh && tp->_t_logstate == TCP_LOG_STATE_OFF &&
tlb->tlb_logstate == TCP_LOG_STATE_OFF) {
tlb->tlb_logstate = TCP_LOG_STATE_RATIO_OFF;
INP_WLOCK(inp);
RECHECK_INP();
(void)tcp_log_state_change(tp, TCP_LOG_STATE_OFF);
done:
INP_WUNLOCK(inp);
}
INP_UNLOCK_ASSERT(inp);
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 (rv);
}
int
tcp_log_set_tag(struct tcpcb *tp, char *tag)
{
struct inpcb *inp = tptoinpcb(tp);
struct tcp_log_id_bucket *tlb;
int tree_locked;
INP_WLOCK_ASSERT(inp);
tree_locked = TREE_UNLOCKED;
tlb = tp->t_lib;
if (tlb == NULL) {
INP_WUNLOCK(inp);
return (EOPNOTSUPP);
}
TCPID_BUCKET_REF(tlb);
INP_WUNLOCK(inp);
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);
}
int
tcp_log_set_id(struct tcpcb *tp, char *id)
{
struct tcp_log_id_bucket *tlb, *tmp_tlb;
struct tcp_log_id_node *tln;
struct inpcb *inp = tptoinpcb(tp);
int tree_locked, rv;
bool bucket_locked, same;
tlb = NULL;
tln = NULL;
tree_locked = TREE_UNLOCKED;
bucket_locked = false;
restart:
INP_WLOCK_ASSERT(inp);
same = ((tp->t_lib != NULL && !strcmp(tp->t_lib->tlb_id, id)) ||
(tp->t_lib == NULL && *id == 0));
if (tp->_t_logstate && STAILQ_FIRST(&tp->t_logs) && !same) {
switch(tp->_t_logstate) {
case TCP_LOG_STATE_HEAD_AUTO:
(void)tcp_log_dump_tp_logbuf(tp, "auto-dumped from head at id switch",
M_NOWAIT, false);
break;
case TCP_LOG_STATE_TAIL_AUTO:
(void)tcp_log_dump_tp_logbuf(tp, "auto-dumped from tail at id switch",
M_NOWAIT, false);
break;
case TCP_LOG_STATE_CONTINUAL:
(void)tcp_log_dump_tp_logbuf(tp, "auto-dumped from continual at id switch",
M_NOWAIT, false);
break;
case TCP_LOG_VIA_BBPOINTS:
(void)tcp_log_dump_tp_logbuf(tp, "auto-dumped from bbpoints at id switch",
M_NOWAIT, false);
break;
}
}
if (same) {
if (tp->t_lib != NULL) {
tcp_log_increment_reqcnt(tp->t_lib);
if ((tp->t_lib->tlb_logstate > TCP_LOG_STATE_OFF) &&
(tp->t_log_state_set == 0)) {
tp->_t_logstate = tp->t_lib->tlb_logstate;
}
if ((tp->t_lib->tlb_loglimit) &&
(tp->t_log_state_set == 0)) {
tp->t_loglimit = tp->t_lib->tlb_loglimit;
}
}
rv = 0;
goto done;
}
if (tp->t_lib != NULL) {
tlb = tp->t_lib;
TCPID_BUCKET_REF(tlb);
INP_WUNLOCK(inp);
if (tree_locked == TREE_UNLOCKED) {
TCPID_TREE_RLOCK();
tree_locked = TREE_RLOCKED;
}
TCPID_BUCKET_LOCK(tlb);
bucket_locked = true;
INP_WLOCK(inp);
if (tcp_log_unref_bucket(tlb, &tree_locked, inp)) {
bucket_locked = false;
tlb = NULL;
}
RECHECK_INP();
if (tlb == NULL || tp->t_lib != tlb) {
KASSERT(bucket_locked || tlb == NULL,
("%s: bucket_locked (%d) and tlb (%p) are "
"inconsistent", __func__, bucket_locked, tlb));
if (bucket_locked) {
TCPID_BUCKET_UNLOCK(tlb);
bucket_locked = false;
tlb = NULL;
}
goto restart;
}
if (tln != NULL)
uma_zfree(tcp_log_id_node_zone, tln);
tln = tp->t_lin;
tlb = NULL;
bucket_locked = false;
if (tcp_log_remove_id_node(inp, tp, NULL, NULL, &tree_locked)) {
RECHECK_INP();
if (tp->t_lib != NULL || tp->t_lin != NULL)
goto restart;
}
}
KASSERT(tp->t_lib == NULL, ("%s: tp->t_lib is not NULL", __func__));
if (*id) {
if (tln == NULL) {
tln = uma_zalloc(tcp_log_id_node_zone,
M_NOWAIT | M_ZERO);
if (tln == NULL) {
rv = ENOBUFS;
goto done;
}
tln->tln_inp = inp;
tln->tln_tp = tp;
}
INP_WUNLOCK(inp);
tcp_log_id_validate_tree_lock(tree_locked);
if (tree_locked == TREE_UNLOCKED) {
TCPID_TREE_RLOCK();
tree_locked = TREE_RLOCKED;
}
refind:
KASSERT(tlb == NULL, ("%s:%d tlb unexpectedly non-NULL",
__func__, __LINE__));
tmp_tlb = RB_FIND(tcp_log_id_tree, &tcp_log_id_head,
(struct tcp_log_id_bucket *) id);
if (tmp_tlb == NULL && tree_locked != TREE_WLOCKED) {
tree_locked = TREE_WLOCKED;
if (!TCPID_TREE_UPGRADE()) {
TCPID_TREE_RUNLOCK();
TCPID_TREE_WLOCK();
goto refind;
}
}
if (tmp_tlb == NULL) {
tlb = uma_zalloc(tcp_log_id_bucket_zone, M_NOWAIT);
if (tlb == NULL) {
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()) {
tlb->tlb_logstate = tcp_log_auto_mode;
} else
tlb->tlb_logstate = TCP_LOG_STATE_OFF;
tlb->tlb_loglimit = 0;
tlb->tlb_tag[0] = '\0';
strncpy(tlb->tlb_id, id, TCP_LOG_ID_LEN - 1);
tlb->tlb_id[TCP_LOG_ID_LEN - 1] = '\0';
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);
bucket_locked = true;
#define FREE_NEW_TLB() do { \
TCPID_BUCKET_LOCK_DESTROY(tlb); \
uma_zfree(tcp_log_id_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)
INP_WLOCK(inp);
RECHECK_INP_CLEAN(FREE_NEW_TLB());
if (tp->t_lib != NULL) {
FREE_NEW_TLB();
goto restart;
}
tmp_tlb = RB_INSERT(tcp_log_id_tree, &tcp_log_id_head,
tlb);
KASSERT(tmp_tlb == NULL,
("%s: Unexpected conflicting bucket (%p) while "
"adding new bucket (%p)", __func__, tmp_tlb, tlb));
if (tmp_tlb != NULL) {
FREE_NEW_TLB();
INP_WUNLOCK(inp);
}
#undef FREE_NEW_TLB
}
if (tmp_tlb != NULL) {
tlb = tmp_tlb;
TCPID_BUCKET_LOCK(tlb);
bucket_locked = true;
INP_UNLOCK_ASSERT(inp);
INP_WLOCK(inp);
RECHECK_INP();
if (tp->t_lib != NULL) {
TCPID_BUCKET_UNLOCK(tlb);
bucket_locked = false;
tlb = NULL;
goto restart;
}
TCPID_BUCKET_REF(tlb);
tcp_log_increment_reqcnt(tlb);
}
tcp_log_grow_tlb(tlb->tlb_id, tp);
SLIST_INSERT_HEAD(&tlb->tlb_head, tln, tln_list);
tp->t_lib = tlb;
tp->t_lin = tln;
if (tp->t_lib->tlb_logstate > TCP_LOG_STATE_OFF) {
tp->_t_logstate = tp->t_lib->tlb_logstate;
}
if (tp->t_lib->tlb_loglimit) {
tp->t_loglimit = tp->t_lib->tlb_loglimit;
}
tln = NULL;
}
rv = 0;
done:
INP_WUNLOCK(inp);
done_noinp:
INP_UNLOCK_ASSERT(inp);
if (bucket_locked) {
TCPID_BUCKET_LOCK_ASSERT(tlb);
TCPID_BUCKET_UNLOCK(tlb);
} else if (tlb != NULL)
TCPID_BUCKET_UNLOCK_ASSERT(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();
if (tln != NULL)
uma_zfree(tcp_log_id_node_zone, tln);
return (rv);
}
size_t
tcp_log_get_id(struct tcpcb *tp, char *buf)
{
size_t len;
INP_LOCK_ASSERT(tptoinpcb(tp));
if (tp->t_lib != NULL) {
len = strlcpy(buf, tp->t_lib->tlb_id, TCP_LOG_ID_LEN);
KASSERT(len < TCP_LOG_ID_LEN,
("%s:%d: tp->t_lib->tlb_id too long (%zu)",
__func__, __LINE__, len));
} else {
*buf = '\0';
len = 0;
}
return (len);
}
size_t
tcp_log_get_tag(struct tcpcb *tp, char *buf)
{
struct inpcb *inp = tptoinpcb(tp);
struct tcp_log_id_bucket *tlb;
size_t len;
int tree_locked;
INP_WLOCK_ASSERT(inp);
tree_locked = TREE_UNLOCKED;
tlb = tp->t_lib;
if (tlb != NULL) {
TCPID_BUCKET_REF(tlb);
INP_WUNLOCK(inp);
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(inp);
*buf = '\0';
len = 0;
}
return (len);
}
u_int
tcp_log_get_id_cnt(struct tcpcb *tp)
{
INP_WLOCK_ASSERT(tptoinpcb(tp));
return ((tp->t_lib == NULL) ? 0 : tp->t_lib->tlb_refcnt);
}
#ifdef TCPLOG_DEBUG_RINGBUF
static inline void
_tcp_log_entry_refcnt_add(struct tcp_log_mem *log_entry, const char *func,
int line)
{
int refcnt;
refcnt = atomic_fetchadd_int(&log_entry->tlm_refcnt, 1);
if (refcnt != 0)
panic("%s:%d: log_entry(%p)->tlm_refcnt is %d (expected 0)",
func, line, log_entry, refcnt);
}
#define tcp_log_entry_refcnt_add(l) \
_tcp_log_entry_refcnt_add((l), __func__, __LINE__)
static inline void
_tcp_log_entry_refcnt_rem(struct tcp_log_mem *log_entry, const char *func,
int line)
{
int refcnt;
refcnt = atomic_fetchadd_int(&log_entry->tlm_refcnt, -1);
if (refcnt != 1)
panic("%s:%d: log_entry(%p)->tlm_refcnt is %d (expected 1)",
func, line, log_entry, refcnt);
}
#define tcp_log_entry_refcnt_rem(l) \
_tcp_log_entry_refcnt_rem((l), __func__, __LINE__)
#else
#define tcp_log_entry_refcnt_add(l)
#define tcp_log_entry_refcnt_rem(l)
#endif
static inline void
tcp_log_free_log_common(struct tcp_log_mem *log_entry, int *count __unused)
{
uma_zfree(tcp_log_zone, log_entry);
#ifdef INVARIANTS
(*count)--;
KASSERT(*count >= 0,
("%s: count unexpectedly negative", __func__));
#endif
}
static void
tcp_log_free_entries(struct tcp_log_stailq *head, int *count)
{
struct tcp_log_mem *log_entry;
while ((log_entry = STAILQ_FIRST(head)) != NULL) {
STAILQ_REMOVE_HEAD(head, tlm_queue);
tcp_log_entry_refcnt_rem(log_entry);
tcp_log_free_log_common(log_entry, count);
}
}
static inline void
tcp_log_remove_log_cleanup(struct tcpcb *tp, struct tcp_log_mem *log_entry)
{
uma_zfree(tcp_log_zone, log_entry);
tp->t_lognum--;
KASSERT(tp->t_lognum >= 0,
("%s: tp->t_lognum unexpectedly negative", __func__));
}
static inline void
tcp_log_remove_log_head(struct tcpcb *tp, struct tcp_log_mem *log_entry)
{
KASSERT(log_entry == STAILQ_FIRST(&tp->t_logs),
("%s: attempt to remove non-HEAD log entry", __func__));
STAILQ_REMOVE_HEAD(&tp->t_logs, tlm_queue);
tcp_log_entry_refcnt_rem(log_entry);
tcp_log_remove_log_cleanup(tp, log_entry);
}
#ifdef TCPLOG_DEBUG_RINGBUF
static int
tcp_log_zone_init(void *mem, int size, int flags __unused)
{
struct tcp_log_mem *tlm;
KASSERT(size >= sizeof(struct tcp_log_mem),
("%s: unexpectedly short (%d) allocation", __func__, size));
tlm = (struct tcp_log_mem *)mem;
tlm->tlm_refcnt = 0;
return (0);
}
static int
tcp_log_zone_ctor(void *mem, int size, void *args __unused, int flags __unused)
{
struct tcp_log_mem *tlm;
KASSERT(size >= sizeof(struct tcp_log_mem),
("%s: unexpectedly short (%d) allocation", __func__, size));
tlm = (struct tcp_log_mem *)mem;
if (tlm->tlm_refcnt != 0)
panic("%s:%d: tlm(%p)->tlm_refcnt is %d (expected 0)",
__func__, __LINE__, tlm, tlm->tlm_refcnt);
return (0);
}
static void
tcp_log_zone_dtor(void *mem, int size, void *args __unused)
{
struct tcp_log_mem *tlm;
KASSERT(size >= sizeof(struct tcp_log_mem),
("%s: unexpectedly short (%d) allocation", __func__, size));
tlm = (struct tcp_log_mem *)mem;
if (tlm->tlm_refcnt != 0)
panic("%s:%d: tlm(%p)->tlm_refcnt is %d (expected 0)",
__func__, __LINE__, tlm, tlm->tlm_refcnt);
}
#endif
void
tcp_log_init(void)
{
tcp_log_zone = uma_zcreate("tcp_log", sizeof(struct tcp_log_mem),
#ifdef TCPLOG_DEBUG_RINGBUF
tcp_log_zone_ctor, tcp_log_zone_dtor, tcp_log_zone_init,
#else
NULL, NULL, NULL,
#endif
NULL, UMA_ALIGN_PTR, 0);
(void)uma_zone_set_max(tcp_log_zone, TCP_LOG_BUF_DEFAULT_GLOBAL_LIMIT);
tcp_log_id_bucket_zone = uma_zcreate("tcp_log_id_bucket",
sizeof(struct tcp_log_id_bucket), NULL, NULL, NULL, NULL,
UMA_ALIGN_PTR, 0);
tcp_log_id_node_zone = uma_zcreate("tcp_log_id_node",
sizeof(struct tcp_log_id_node), NULL, NULL, NULL, NULL,
UMA_ALIGN_PTR, 0);
#ifdef TCPLOG_DEBUG_COUNTERS
tcp_log_queued = counter_u64_alloc(M_WAITOK);
tcp_log_que_fail1 = counter_u64_alloc(M_WAITOK);
tcp_log_que_fail2 = counter_u64_alloc(M_WAITOK);
tcp_log_que_fail3 = counter_u64_alloc(M_WAITOK);
tcp_log_que_fail4 = counter_u64_alloc(M_WAITOK);
tcp_log_que_fail5 = counter_u64_alloc(M_WAITOK);
tcp_log_que_copyout = counter_u64_alloc(M_WAITOK);
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);
callout_init(&tcp_log_expireq_callout, 1);
}
void
tcp_log_tcpcbinit(struct tcpcb *tp)
{
STAILQ_INIT(&tp->t_logs);
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;
}
}
static void
tcp_log_expire(void *unused __unused)
{
struct tcp_log_id_bucket *tlb;
struct tcp_log_id_node *tln;
sbintime_t expiry_limit;
int tree_locked;
TCPLOG_EXPIREQ_LOCK();
if (callout_pending(&tcp_log_expireq_callout)) {
TCPLOG_EXPIREQ_UNLOCK();
return;
}
expiry_limit = getsbinuptime() + SBT_1S;
tree_locked = TREE_UNLOCKED;
while ((tln = STAILQ_FIRST(&tcp_log_expireq_head)) != NULL &&
tln->tln_expiretime <= expiry_limit) {
if (!callout_active(&tcp_log_expireq_callout)) {
TCPLOG_EXPIREQ_UNLOCK();
return;
}
STAILQ_REMOVE_HEAD(&tcp_log_expireq_head, tln_expireq);
tln->tln_expiretime = SBT_MAX;
TCPLOG_EXPIREQ_UNLOCK();
tlb = tln->tln_bucket;
TCPID_BUCKET_LOCK(tlb);
if (tcp_log_remove_id_node(NULL, NULL, tlb, tln, &tree_locked)) {
tcp_log_id_validate_tree_lock(tree_locked);
if (tree_locked == TREE_WLOCKED)
TCPID_TREE_WUNLOCK();
else
TCPID_TREE_RUNLOCK();
tree_locked = TREE_UNLOCKED;
}
INP_WLOCK(tln->tln_inp);
if (!in_pcbrele_wlocked(tln->tln_inp))
INP_WUNLOCK(tln->tln_inp);
tcp_log_free_entries(&tln->tln_entries, &tln->tln_count);
uma_zfree(tcp_log_id_node_zone, tln);
TCPLOG_EXPIREQ_LOCK();
}
callout_deactivate(&tcp_log_expireq_callout);
if (tln != NULL) {
expiry_limit = getsbinuptime() + TCP_LOG_EXPIRE_INTVL;
if (expiry_limit < tln->tln_expiretime)
expiry_limit = tln->tln_expiretime;
callout_reset_sbt(&tcp_log_expireq_callout, expiry_limit,
SBT_1S, tcp_log_expire, NULL, C_ABSOLUTE);
}
TCPLOG_EXPIREQ_UNLOCK();
return;
}
static void
tcp_log_move_tp_to_node(struct tcpcb *tp, struct tcp_log_id_node *tln)
{
struct inpcb *inp = tptoinpcb(tp);
INP_WLOCK_ASSERT(inp);
tln->tln_ie = inp->inp_inc.inc_ie;
if (inp->inp_inc.inc_flags & INC_ISIPV6)
tln->tln_af = AF_INET6;
else
tln->tln_af = AF_INET;
tln->tln_entries = tp->t_logs;
tln->tln_count = tp->t_lognum;
tln->tln_bucket = tp->t_lib;
STAILQ_INIT(&tp->t_logs);
tp->t_lognum = 0;
}
void
tcp_log_tcpcbfini(struct tcpcb *tp)
{
struct tcp_log_id_node *tln, *tln_first;
struct tcp_log_mem *log_entry;
sbintime_t callouttime;
INP_WLOCK_ASSERT(tptoinpcb(tp));
if (tp->_t_logstate) {
union tcp_log_stackspecific log;
struct timeval tv;
#ifdef TCP_ACCOUNTING
struct tcp_log_buffer *lgb;
int i;
memset(&log, 0, sizeof(log));
if (tp->t_flags2 & TF2_TCP_ACCOUNTING) {
for (i = 0; i < TCP_NUM_CNT_COUNTERS; i++) {
log.u_raw.u64_flex[i] = tp->tcp_cnt_counters[i];
}
lgb = tcp_log_event(tp, NULL,
NULL,
NULL,
TCP_LOG_ACCOUNTING, 0,
0, &log, false, NULL, NULL, 0, &tv);
if (lgb != NULL) {
lgb->tlb_flex1 = TCP_NUM_CNT_COUNTERS;
lgb->tlb_flex2 = 1;
} else
goto skip_out;
for (i = 0; i<TCP_NUM_CNT_COUNTERS; i++) {
log.u_raw.u64_flex[i] = tp->tcp_proc_time[i];
}
lgb = tcp_log_event(tp, NULL,
NULL,
NULL,
TCP_LOG_ACCOUNTING, 0,
0, &log, false, NULL, NULL, 0, &tv);
if (lgb != NULL) {
lgb->tlb_flex1 = TCP_NUM_CNT_COUNTERS;
lgb->tlb_flex2 = 2;
}
}
skip_out:
#endif
log.u_bbr.timeStamp = tcp_get_usecs(&tv);
log.u_bbr.cur_del_rate = tp->t_end_info;
(void)tcp_log_event(tp, NULL,
NULL,
NULL,
TCP_LOG_CONNEND, 0,
0, &log, false, NULL, NULL, 0, &tv);
}
switch(tp->_t_logstate) {
case TCP_LOG_STATE_HEAD_AUTO:
(void)tcp_log_dump_tp_logbuf(tp, "auto-dumped from head",
M_NOWAIT, false);
break;
case TCP_LOG_STATE_TAIL_AUTO:
(void)tcp_log_dump_tp_logbuf(tp, "auto-dumped from tail",
M_NOWAIT, false);
break;
case TCP_LOG_VIA_BBPOINTS:
(void)tcp_log_dump_tp_logbuf(tp, "auto-dumped from bbpoints",
M_NOWAIT, false);
break;
case TCP_LOG_STATE_CONTINUAL:
(void)tcp_log_dump_tp_logbuf(tp, "auto-dumped from continual",
M_NOWAIT, false);
break;
}
if (tp->t_lin != NULL) {
struct inpcb *inp = tptoinpcb(tp);
tln = tp->t_lin;
KASSERT(tln->tln_inp == inp,
("%s: Mismatched inp (tln->tln_inp=%p, tp inpcb=%p)",
__func__, tln->tln_inp, inp));
tcp_log_move_tp_to_node(tp, tln);
tp->t_lin = NULL;
tp->t_lib = NULL;
in_pcbref(inp);
tln->tln_expiretime = getsbinuptime();
TCPLOG_EXPIREQ_LOCK();
if (tln->tln_count) {
tln->tln_expiretime += TCP_LOG_EXPIRE_TIME;
if (STAILQ_EMPTY(&tcp_log_expireq_head) &&
!callout_active(&tcp_log_expireq_callout)) {
callout_reset_sbt(&tcp_log_expireq_callout,
tln->tln_expiretime, SBT_1S, tcp_log_expire,
NULL, C_ABSOLUTE);
}
STAILQ_INSERT_TAIL(&tcp_log_expireq_head, tln,
tln_expireq);
} else {
callouttime = tln->tln_expiretime +
TCP_LOG_EXPIRE_INTVL;
tln_first = STAILQ_FIRST(&tcp_log_expireq_head);
if ((tln_first == NULL ||
callouttime < tln_first->tln_expiretime) &&
(callout_pending(&tcp_log_expireq_callout) ||
!callout_active(&tcp_log_expireq_callout))) {
callout_reset_sbt(&tcp_log_expireq_callout,
callouttime, SBT_1S, tcp_log_expire, NULL,
C_ABSOLUTE);
}
if (tln_first == NULL ||
tln->tln_expiretime < tln_first->tln_expiretime)
STAILQ_INSERT_HEAD(&tcp_log_expireq_head, tln,
tln_expireq);
else
STAILQ_INSERT_AFTER(&tcp_log_expireq_head,
tln_first, tln, tln_expireq);
}
TCPLOG_EXPIREQ_UNLOCK();
atomic_store_rel_int(&tln->tln_closed, 1);
} else {
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;
}
static void
tcp_log_purge_tp_logbuf(struct tcpcb *tp)
{
struct tcp_log_mem *log_entry;
INP_WLOCK_ASSERT(tptoinpcb(tp));
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;
}
struct tcp_log_buffer *
tcp_log_event(struct tcpcb *tp, struct tcphdr *th, struct sockbuf *rxbuf,
struct sockbuf *txbuf, uint8_t eventid, int errornum, uint32_t len,
union tcp_log_stackspecific *stackinfo, int th_hostorder,
const char *output_caller, const char *func, int line, const struct timeval *itv)
{
struct tcp_log_mem *log_entry;
struct tcp_log_buffer *log_buf;
int attempt_count = 0;
struct tcp_log_verbose *log_verbose;
uint32_t logsn;
KASSERT((func == NULL && line == 0) || (func != NULL && line > 0),
("%s called with inconsistent func (%p) and line (%d) arguments",
__func__, func, line));
INP_WLOCK_ASSERT(tptoinpcb(tp));
if (tcp_disable_all_bb_logs) {
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 ||
tp->_t_logstate == TCP_LOG_STATE_HEAD_AUTO ||
tp->_t_logstate == TCP_LOG_VIA_BBPOINTS ||
tp->_t_logstate == TCP_LOG_STATE_TAIL_AUTO,
("%s called with unexpected tp->_t_logstate (%d)", __func__,
tp->_t_logstate));
logsn = tp->t_logsn++;
retry:
if (tp->t_lognum < tp->t_loglimit) {
if ((log_entry = uma_zalloc(tcp_log_zone, M_NOWAIT)) != NULL)
tp->t_lognum++;
} else
log_entry = NULL;
if (log_entry == NULL) {
if (tp->t_lib == NULL && (tp->t_flags2 & TF2_LOG_AUTO) &&
!tcp_log_auto_all) {
if (tcp_log_state_change(tp, TCP_LOG_STATE_CLEAR)) {
#ifdef INVARIANTS
panic("%s:%d: tcp_log_state_change() failed "
"to set tp %p to TCP_LOG_STATE_CLEAR",
__func__, __LINE__, tp);
#endif
tp->_t_logstate = TCP_LOG_STATE_OFF;
}
return (NULL);
}
if (tp->_t_logstate == TCP_LOG_STATE_HEAD_AUTO &&
!tcp_log_dump_tp_logbuf(tp, "auto-dumped from head",
M_NOWAIT, false)) {
tp->_t_logstate = TCP_LOG_STATE_OFF;
return(NULL);
} else if ((tp->_t_logstate == TCP_LOG_STATE_CONTINUAL) &&
!tcp_log_dump_tp_logbuf(tp, "auto-dumped from continual",
M_NOWAIT, false)) {
if (attempt_count == 0) {
attempt_count++;
goto retry;
}
#ifdef TCPLOG_DEBUG_COUNTERS
counter_u64_add(tcp_log_que_fail4, 1);
#endif
return(NULL);
} else if ((tp->_t_logstate == TCP_LOG_VIA_BBPOINTS) &&
!tcp_log_dump_tp_logbuf(tp, "auto-dumped from bbpoints",
M_NOWAIT, false)) {
if (attempt_count == 0) {
attempt_count++;
goto retry;
}
#ifdef TCPLOG_DEBUG_COUNTERS
counter_u64_add(tcp_log_que_fail4, 1);
#endif
return(NULL);
} else if (tp->_t_logstate == TCP_LOG_STATE_HEAD_AUTO)
return(NULL);
if (tp->_t_logstate == TCP_LOG_STATE_HEAD) {
tp->_t_logstate = TCP_LOG_STATE_OFF;
return(NULL);
}
if ((log_entry = STAILQ_FIRST(&tp->t_logs)) == NULL)
return(NULL);
STAILQ_REMOVE_HEAD(&tp->t_logs, tlm_queue);
tcp_log_entry_refcnt_rem(log_entry);
}
KASSERT(log_entry != NULL,
("%s: log_entry unexpectedly NULL", __func__));
log_buf = &log_entry->tlm_buf;
log_verbose = &log_entry->tlm_v;
if (itv == NULL)
microuptime(&log_buf->tlb_tv);
else
memcpy(&log_buf->tlb_tv, itv, sizeof(struct timeval));
log_buf->tlb_ticks = ticks;
log_buf->tlb_sn = logsn;
log_buf->tlb_stackid = tp->t_fb->tfb_id;
log_buf->tlb_eventid = eventid;
log_buf->tlb_eventflags = 0;
log_buf->tlb_errno = errornum;
if (rxbuf != NULL) {
log_buf->tlb_eventflags |= TLB_FLAG_RXBUF;
log_buf->tlb_rxbuf.tls_sb_acc = rxbuf->sb_acc;
log_buf->tlb_rxbuf.tls_sb_ccc = rxbuf->sb_ccc;
log_buf->tlb_rxbuf.tls_sb_spare = 0;
} else {
log_buf->tlb_rxbuf.tls_sb_acc = 0;
log_buf->tlb_rxbuf.tls_sb_ccc = 0;
}
if (txbuf != NULL) {
log_buf->tlb_eventflags |= TLB_FLAG_TXBUF;
log_buf->tlb_txbuf.tls_sb_acc = txbuf->sb_acc;
log_buf->tlb_txbuf.tls_sb_ccc = txbuf->sb_ccc;
log_buf->tlb_txbuf.tls_sb_spare = 0;
} else {
log_buf->tlb_txbuf.tls_sb_acc = 0;
log_buf->tlb_txbuf.tls_sb_ccc = 0;
}
log_buf->tlb_state = tp->t_state;
log_buf->tlb_starttime = tp->t_starttime;
log_buf->tlb_iss = tp->iss;
log_buf->tlb_flags = tp->t_flags;
log_buf->tlb_snd_una = tp->snd_una;
log_buf->tlb_snd_max = tp->snd_max;
log_buf->tlb_snd_cwnd = tp->snd_cwnd;
log_buf->tlb_snd_nxt = tp->snd_nxt;
log_buf->tlb_snd_recover = tp->snd_recover;
log_buf->tlb_snd_wnd = tp->snd_wnd;
log_buf->tlb_snd_ssthresh = tp->snd_ssthresh;
log_buf->tlb_srtt = tp->t_srtt;
log_buf->tlb_rttvar = tp->t_rttvar;
log_buf->tlb_rcv_up = tp->rcv_up;
log_buf->tlb_rcv_adv = tp->rcv_adv;
log_buf->tlb_flags2 = tp->t_flags2;
log_buf->tlb_rcv_nxt = tp->rcv_nxt;
log_buf->tlb_rcv_wnd = tp->rcv_wnd;
log_buf->tlb_dupacks = tp->t_dupacks;
log_buf->tlb_segqlen = tp->t_segqlen;
log_buf->tlb_snd_numholes = tp->snd_numholes;
log_buf->tlb_flex1 = 0;
log_buf->tlb_flex2 = 0;
log_buf->tlb_fbyte_in = tp->t_fbyte_in;
log_buf->tlb_fbyte_out = tp->t_fbyte_out;
log_buf->tlb_snd_scale = tp->snd_scale;
log_buf->tlb_rcv_scale = tp->rcv_scale;
log_buf->_pad[0] = 0;
log_buf->_pad[1] = 0;
log_buf->_pad[2] = 0;
if (stackinfo != NULL) {
memcpy(&log_buf->tlb_stackinfo, stackinfo,
sizeof(log_buf->tlb_stackinfo));
log_buf->tlb_eventflags |= TLB_FLAG_STACKINFO;
}
log_buf->tlb_len = len;
if (th) {
int optlen;
log_buf->tlb_eventflags |= TLB_FLAG_HDR;
log_buf->tlb_th = *th;
if (th_hostorder)
tcp_fields_to_net(&log_buf->tlb_th);
optlen = (th->th_off << 2) - sizeof (struct tcphdr);
if (optlen > 0)
memcpy(log_buf->tlb_opts, th + 1, optlen);
} else {
memset(&log_buf->tlb_th, 0, sizeof(*th));
}
if (func != NULL) {
log_buf->tlb_eventflags |= TLB_FLAG_VERBOSE;
if (output_caller != NULL)
strlcpy(log_verbose->tlv_snd_frm, output_caller,
TCP_FUNC_LEN);
else
*log_verbose->tlv_snd_frm = 0;
strlcpy(log_verbose->tlv_trace_func, func, TCP_FUNC_LEN);
log_verbose->tlv_trace_line = line;
}
STAILQ_INSERT_TAIL(&tp->t_logs, log_entry, tlm_queue);
tcp_log_entry_refcnt_add(log_entry);
return (log_buf);
}
int
tcp_log_state_change(struct tcpcb *tp, int state)
{
struct tcp_log_mem *log_entry;
int rv;
INP_WLOCK_ASSERT(tptoinpcb(tp));
rv = 0;
switch(state) {
case TCP_LOG_STATE_CLEAR:
while ((log_entry = STAILQ_FIRST(&tp->t_logs)) != NULL)
tcp_log_remove_log_head(tp, log_entry);
case TCP_LOG_STATE_OFF:
tp->_t_logstate = TCP_LOG_STATE_OFF;
break;
case TCP_LOG_STATE_TAIL:
case TCP_LOG_STATE_HEAD:
case TCP_LOG_STATE_CONTINUAL:
case TCP_LOG_VIA_BBPOINTS:
case TCP_LOG_STATE_HEAD_AUTO:
case TCP_LOG_STATE_TAIL_AUTO:
if (tp->t_lib == NULL ||
tp->t_lib->tlb_logstate != TCP_LOG_STATE_RATIO_OFF) {
tp->_t_logstate = state;
} else {
rv = ECANCELED;
tp->_t_logstate = TCP_LOG_STATE_OFF;
}
break;
default:
return (EINVAL);
}
if (tcp_disable_all_bb_logs) {
tp->_t_logstate = TCP_LOG_STATE_OFF;
rv = EBUSY;
}
tp->t_flags2 &= ~(TF2_LOG_AUTO);
return (rv);
}
void
tcp_log_drain(struct tcpcb *tp)
{
struct tcp_log_mem *log_entry, *next;
int target, skip;
INP_WLOCK_ASSERT(tptoinpcb(tp));
if ((target = tp->t_lognum / 2) == 0)
return;
if (tp->_t_logstate == TCP_LOG_STATE_HEAD) {
skip = tp->t_lognum - target;
STAILQ_FOREACH(log_entry, &tp->t_logs, tlm_queue)
if (!--skip)
break;
KASSERT(log_entry != NULL,
("%s: skipped through all entries!", __func__));
if (log_entry == NULL)
return;
while ((next = STAILQ_NEXT(log_entry, tlm_queue)) != NULL) {
STAILQ_REMOVE_AFTER(&tp->t_logs, log_entry, tlm_queue);
tcp_log_entry_refcnt_rem(next);
tcp_log_remove_log_cleanup(tp, next);
#ifdef INVARIANTS
target--;
#endif
}
KASSERT(target == 0,
("%s: After removing from tail, target was %d", __func__,
target));
} else if (tp->_t_logstate == TCP_LOG_STATE_HEAD_AUTO) {
(void)tcp_log_dump_tp_logbuf(tp, "auto-dumped from head at drain",
M_NOWAIT, false);
} else if (tp->_t_logstate == TCP_LOG_STATE_TAIL_AUTO) {
(void)tcp_log_dump_tp_logbuf(tp, "auto-dumped from tail at drain",
M_NOWAIT, false);
} else if (tp->_t_logstate == TCP_LOG_VIA_BBPOINTS) {
(void)tcp_log_dump_tp_logbuf(tp, "auto-dumped from bbpoints",
M_NOWAIT, false);
} else if (tp->_t_logstate == TCP_LOG_STATE_CONTINUAL) {
(void)tcp_log_dump_tp_logbuf(tp, "auto-dumped from continual",
M_NOWAIT, false);
} else {
while ((log_entry = STAILQ_FIRST(&tp->t_logs)) != NULL &&
target--)
tcp_log_remove_log_head(tp, log_entry);
KASSERT(target <= 0,
("%s: After removing from head, target was %d", __func__,
target));
KASSERT(tp->t_lognum > 0,
("%s: After removing from head, tp->t_lognum was %d",
__func__, target));
KASSERT(log_entry != NULL,
("%s: After removing from head, the tailq was empty",
__func__));
}
}
static inline int
tcp_log_copyout(struct sockopt *sopt, void *src, void *dst, size_t len)
{
if (sopt->sopt_td != NULL)
return (copyout(src, dst, len));
bcopy(src, dst, len);
return (0);
}
static int
tcp_log_logs_to_buf(struct sockopt *sopt, struct tcp_log_stailq *log_tailqp,
struct tcp_log_buffer **end, int count)
{
struct tcp_log_buffer *out_entry;
struct tcp_log_mem *log_entry;
size_t entrysize;
int error;
#ifdef INVARIANTS
int orig_count = count;
#endif
error = 0;
out_entry = (struct tcp_log_buffer *) sopt->sopt_val;
STAILQ_FOREACH(log_entry, log_tailqp, tlm_queue) {
count--;
KASSERT(count >= 0,
("%s:%d: Exceeded expected count (%d) processing list %p",
__func__, __LINE__, orig_count, log_tailqp));
#ifdef TCPLOG_DEBUG_COUNTERS
counter_u64_add(tcp_log_que_copyout, 1);
#endif
if (log_entry->tlm_buf.tlb_eventflags & TLB_FLAG_HDR)
entrysize = sizeof(struct tcp_log_buffer);
else
entrysize = offsetof(struct tcp_log_buffer, tlb_th);
error = tcp_log_copyout(sopt, &log_entry->tlm_buf, out_entry,
entrysize);
if (error)
break;
if (!(log_entry->tlm_buf.tlb_eventflags & TLB_FLAG_HDR)) {
error = tcp_log_copyout(sopt, zerobuf,
((uint8_t *)out_entry) + entrysize,
sizeof(struct tcp_log_buffer) - entrysize);
}
if (log_entry->tlm_buf.tlb_eventflags & TLB_FLAG_VERBOSE) {
error = tcp_log_copyout(sopt, &log_entry->tlm_v,
out_entry->tlb_verbose,
sizeof(struct tcp_log_verbose));
if (error)
break;
out_entry = (struct tcp_log_buffer *)
(((uint8_t *) (out_entry + 1)) +
sizeof(struct tcp_log_verbose));
} else
out_entry++;
}
*end = out_entry;
KASSERT(error || count == 0,
("%s:%d: Less than expected count (%d) processing list %p"
" (%d remain)", __func__, __LINE__, orig_count,
log_tailqp, count));
return (error);
}
int
tcp_log_getlogbuf(struct sockopt *sopt, struct tcpcb *tp)
{
struct tcp_log_stailq log_tailq;
struct tcp_log_mem *log_entry, *log_next;
struct tcp_log_buffer *out_entry;
struct inpcb *inp = tptoinpcb(tp);
size_t outsize, entrysize;
int error, outnum;
INP_WLOCK_ASSERT(inp);
#ifndef INVARIANTS
if (sopt->sopt_valsize / (sizeof(struct tcp_log_buffer) +
sizeof(struct tcp_log_verbose)) >= tp->t_lognum) {
log_entry = STAILQ_LAST(&tp->t_logs, tcp_log_mem, tlm_queue);
log_next = NULL;
outsize = 0;
outnum = tp->t_lognum;
} else {
#endif
outsize = outnum = 0;
log_entry = NULL;
STAILQ_FOREACH(log_next, &tp->t_logs, tlm_queue) {
entrysize = sizeof(struct tcp_log_buffer);
if (log_next->tlm_buf.tlb_eventflags &
TLB_FLAG_VERBOSE)
entrysize += sizeof(struct tcp_log_verbose);
if ((sopt->sopt_valsize - outsize) < entrysize)
break;
outsize += entrysize;
outnum++;
log_entry = log_next;
}
KASSERT(outsize <= sopt->sopt_valsize,
("%s: calculated output size (%zu) greater than available"
"space (%zu)", __func__, outsize, sopt->sopt_valsize));
#ifndef INVARIANTS
}
#endif
if (sopt->sopt_val == NULL) {
INP_WUNLOCK(inp);
if (outsize == 0) {
outsize = outnum * (sizeof(struct tcp_log_buffer) +
sizeof(struct tcp_log_verbose));
}
if (sopt->sopt_valsize > outsize)
sopt->sopt_valsize = outsize;
return (0);
}
if (log_entry != NULL && log_next == NULL) {
KASSERT(outnum == tp->t_lognum,
("%s:%d: outnum (%d) should match tp->t_lognum (%d)",
__func__, __LINE__, outnum, tp->t_lognum));
log_tailq = tp->t_logs;
tp->t_lognum = 0;
STAILQ_INIT(&tp->t_logs);
} else if (log_entry != NULL) {
KASSERT(outnum < tp->t_lognum,
("%s:%d: outnum (%d) not less than tp->t_lognum (%d)",
__func__, __LINE__, outnum, tp->t_lognum));
STAILQ_FIRST(&log_tailq) = STAILQ_FIRST(&tp->t_logs);
STAILQ_FIRST(&tp->t_logs) = STAILQ_NEXT(log_entry, tlm_queue);
KASSERT(STAILQ_NEXT(log_entry, tlm_queue) != NULL,
("%s:%d: tp->t_logs is unexpectedly shorter than expected"
"(tp: %p, log_tailq: %p, outnum: %d, tp->t_lognum: %d)",
__func__, __LINE__, tp, &log_tailq, outnum, tp->t_lognum));
STAILQ_NEXT(log_entry, tlm_queue) = NULL;
log_tailq.stqh_last = &STAILQ_NEXT(log_entry, tlm_queue);
tp->t_lognum -= outnum;
} else
STAILQ_INIT(&log_tailq);
INP_WUNLOCK(inp);
error = tcp_log_logs_to_buf(sopt, &log_tailq, &out_entry, outnum);
if (error) {
INP_WLOCK(inp);
if ((inp->inp_flags & INP_DROPPED) == 0) {
tp = intotcpcb(inp);
STAILQ_CONCAT(&log_tailq, &tp->t_logs);
tp->t_logs = log_tailq;
tp->t_lognum += outnum;
}
INP_WUNLOCK(inp);
} else {
KASSERT(((caddr_t)out_entry - (caddr_t)sopt->sopt_val) ==
outsize, ("%s: Actual output size (%zu) != "
"calculated output size (%zu)", __func__,
(size_t)((caddr_t)out_entry - (caddr_t)sopt->sopt_val),
outsize));
STAILQ_FOREACH_SAFE(log_entry, &log_tailq, tlm_queue, log_next) {
tcp_log_entry_refcnt_rem(log_entry);
uma_zfree(tcp_log_zone, log_entry);
}
}
sopt->sopt_valsize = (size_t)((caddr_t)out_entry -
(caddr_t)sopt->sopt_val);
return (error);
}
static void
tcp_log_free_queue(struct tcp_log_dev_queue *param)
{
struct tcp_log_dev_log_queue *entry;
KASSERT(param != NULL, ("%s: called with NULL param", __func__));
if (param == NULL)
return;
entry = (struct tcp_log_dev_log_queue *)param;
tcp_log_free_entries(&entry->tldl_entries, &entry->tldl_count);
if (entry->tldl_common.tldq_buf != NULL)
free(entry->tldl_common.tldq_buf, M_TCPLOGDEV);
free(entry, M_TCPLOGDEV);
}
static struct tcp_log_common_header *
tcp_log_expandlogbuf(struct tcp_log_dev_queue *param)
{
struct tcp_log_dev_log_queue *entry;
struct tcp_log_header *hdr;
uint8_t *end;
struct sockopt sopt;
int error;
entry = (struct tcp_log_dev_log_queue *)param;
sopt.sopt_valsize = sizeof(struct tcp_log_header) +
entry->tldl_count * (sizeof(struct tcp_log_buffer) +
sizeof(struct tcp_log_verbose));
hdr = malloc(sopt.sopt_valsize, M_TCPLOGDEV, M_NOWAIT);
if (hdr == NULL) {
#ifdef TCPLOG_DEBUG_COUNTERS
counter_u64_add(tcp_log_que_fail5, entry->tldl_count);
#endif
return (NULL);
}
sopt.sopt_val = hdr + 1;
sopt.sopt_valsize -= sizeof(struct tcp_log_header);
sopt.sopt_td = NULL;
error = tcp_log_logs_to_buf(&sopt, &entry->tldl_entries,
(struct tcp_log_buffer **)&end, entry->tldl_count);
if (error) {
free(hdr, M_TCPLOGDEV);
return (NULL);
}
tcp_log_free_entries(&entry->tldl_entries, &entry->tldl_count);
entry->tldl_count = 0;
memset(hdr, 0, sizeof(struct tcp_log_header));
hdr->tlh_version = TCP_LOG_BUF_VER;
hdr->tlh_type = TCP_LOG_DEV_TYPE_BBR;
hdr->tlh_length = end - (uint8_t *)hdr;
hdr->tlh_ie = entry->tldl_ie;
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);
}
int
tcp_log_dump_tp_logbuf(struct tcpcb *tp, char *reason, int how, bool force)
{
struct tcp_log_dev_log_queue *entry;
struct inpcb *inp = tptoinpcb(tp);
#ifdef TCPLOG_DEBUG_COUNTERS
int num_entries;
#endif
INP_WLOCK_ASSERT(inp);
if (tp->t_lognum == 0)
return (0);
if (tp->t_lib == NULL && (tp->t_flags2 & TF2_LOG_AUTO) &&
!tcp_log_auto_all && !force) {
struct tcp_log_mem *log_entry;
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;
return (0);
}
entry = malloc(sizeof(struct tcp_log_dev_log_queue), M_TCPLOGDEV,
M_NOWAIT);
if (entry == NULL && (how & M_NOWAIT)) {
#ifdef TCPLOG_DEBUG_COUNTERS
counter_u64_add(tcp_log_que_fail3, 1);
#endif
return (ENOBUFS);
}
if (entry == NULL) {
INP_WUNLOCK(inp);
entry = malloc(sizeof(struct tcp_log_dev_log_queue),
M_TCPLOGDEV, M_WAITOK);
INP_WLOCK(inp);
if (inp->inp_flags & INP_DROPPED) {
free(entry, M_TCPLOGDEV);
#ifdef TCPLOG_DEBUG_COUNTERS
counter_u64_add(tcp_log_que_fail2, 1);
#endif
return (ECONNRESET);
}
tp = intotcpcb(inp);
if (tp->t_lognum == 0) {
free(entry, M_TCPLOGDEV);
return (0);
}
}
if (tp->t_lib != NULL) {
strlcpy(entry->tldl_id, tp->t_lib->tlb_id, TCP_LOG_ID_LEN);
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
strlcpy(entry->tldl_reason, "UNKNOWN", TCP_LOG_REASON_LEN);
entry->tldl_ie = inp->inp_inc.inc_ie;
if (inp->inp_inc.inc_flags & INC_ISIPV6)
entry->tldl_af = AF_INET6;
else
entry->tldl_af = AF_INET;
entry->tldl_entries = tp->t_logs;
entry->tldl_count = tp->t_lognum;
entry->tldl_common.tldq_buf = NULL;
entry->tldl_common.tldq_xform = tcp_log_expandlogbuf;
entry->tldl_common.tldq_dtor = tcp_log_free_queue;
#ifdef TCPLOG_DEBUG_COUNTERS
num_entries = tp->t_lognum;
#endif
tp->t_lognum = 0;
STAILQ_INIT(&tp->t_logs);
if (tcp_log_dev_add_log((struct tcp_log_dev_queue *)entry)) {
tcp_log_free_queue((struct tcp_log_dev_queue *)entry);
#ifdef TCPLOG_DEBUG_COUNTERS
counter_u64_add(tcp_log_que_fail1, num_entries);
} else {
counter_u64_add(tcp_log_queued, num_entries);
#endif
}
return (0);
}
static int
tcp_log_dump_node_logbuf(struct tcp_log_id_node *tln, char *reason, int how)
{
struct tcp_log_dev_log_queue *entry;
struct tcp_log_id_bucket *tlb;
tlb = tln->tln_bucket;
TCPID_BUCKET_LOCK_ASSERT(tlb);
KASSERT(tlb->tlb_refcnt > 0,
("%s:%d: Called with unreferenced bucket (tln=%p, tlb=%p)",
__func__, __LINE__, tln, tlb));
KASSERT(tln->tln_closed,
("%s:%d: Called for node with tln_closed==false (tln=%p)",
__func__, __LINE__, tln));
if (tln->tln_count == 0)
return (0);
entry = malloc(sizeof(struct tcp_log_dev_log_queue), M_TCPLOGDEV,
M_NOWAIT);
if (entry == NULL && (how & M_NOWAIT))
return (ENOBUFS);
if (entry == NULL) {
TCPID_BUCKET_UNLOCK(tlb);
entry = malloc(sizeof(struct tcp_log_dev_log_queue),
M_TCPLOGDEV, M_WAITOK);
TCPID_BUCKET_LOCK(tlb);
}
entry->tldl_common.tldq_buf = NULL;
entry->tldl_common.tldq_xform = tcp_log_expandlogbuf;
entry->tldl_common.tldq_dtor = tcp_log_free_queue;
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
strlcpy(entry->tldl_reason, "UNKNOWN", TCP_LOG_REASON_LEN);
entry->tldl_ie = tln->tln_ie;
entry->tldl_entries = tln->tln_entries;
entry->tldl_count = tln->tln_count;
entry->tldl_af = tln->tln_af;
if (tcp_log_dev_add_log((struct tcp_log_dev_queue *)entry))
tcp_log_free_queue((struct tcp_log_dev_queue *)entry);
return (0);
}
#define LOCAL_SAVE 10
static void
tcp_log_dumpbucketlogs(struct tcp_log_id_bucket *tlb, char *reason)
{
struct tcp_log_id_node local_entries[LOCAL_SAVE];
struct inpcb *inp;
struct tcpcb *tp;
struct tcp_log_id_node *cur_tln, *prev_tln, *tmp_tln;
int i, num_local_entries, tree_locked;
bool expireq_locked;
TCPID_BUCKET_LOCK_ASSERT(tlb);
TCPID_BUCKET_REF(tlb);
expireq_locked = false;
num_local_entries = 0;
prev_tln = NULL;
tree_locked = TREE_UNLOCKED;
SLIST_FOREACH_SAFE(cur_tln, &tlb->tlb_head, tln_list, tmp_tln) {
if (cur_tln->tln_closed) {
no_inp:
if (!expireq_locked) {
TCPLOG_EXPIREQ_LOCK();
expireq_locked = true;
}
KASSERT(cur_tln->tln_expiretime > (sbintime_t) 0,
("%s:%d: node on the expire queue without positive "
"expire time", __func__, __LINE__));
if (cur_tln->tln_expiretime == SBT_MAX) {
prev_tln = cur_tln;
continue;
}
STAILQ_REMOVE(&tcp_log_expireq_head, cur_tln,
tcp_log_id_node, tln_expireq);
if (prev_tln != NULL)
SLIST_REMOVE_AFTER(prev_tln, tln_list);
else
SLIST_REMOVE_HEAD(&tlb->tlb_head, tln_list);
TCPLOG_EXPIREQ_UNLOCK();
expireq_locked = false;
INP_WLOCK(cur_tln->tln_inp);
if (!in_pcbrele_wlocked(cur_tln->tln_inp))
INP_WUNLOCK(cur_tln->tln_inp);
if (tcp_log_unref_bucket(tlb, &tree_locked, NULL)) {
#ifdef INVARIANTS
panic("%s: Bucket refcount unexpectedly 0.",
__func__);
#endif
tcp_log_free_entries(&cur_tln->tln_entries,
&cur_tln->tln_count);
uma_zfree(tcp_log_id_node_zone, cur_tln);
goto done;
}
if (tcp_log_dump_node_logbuf(cur_tln, reason,
M_NOWAIT)) {
if (num_local_entries < LOCAL_SAVE) {
local_entries[num_local_entries] =
*cur_tln;
num_local_entries++;
} else {
tcp_log_free_entries(
&cur_tln->tln_entries,
&cur_tln->tln_count);
}
}
uma_zfree(tcp_log_id_node_zone, cur_tln);
continue;
}
if (expireq_locked) {
TCPLOG_EXPIREQ_UNLOCK();
expireq_locked = false;
}
inp = cur_tln->tln_inp;
INP_WLOCK(inp);
if (cur_tln->tln_closed) {
INP_WUNLOCK(inp);
goto no_inp;
}
tp = cur_tln->tln_tp;
if (tcp_log_dump_tp_logbuf(tp, reason, M_NOWAIT, true) &&
num_local_entries < LOCAL_SAVE) {
tcp_log_move_tp_to_node(tp,
&local_entries[num_local_entries]);
local_entries[num_local_entries].tln_closed = 1;
KASSERT(local_entries[num_local_entries].tln_bucket ==
tlb, ("%s: %d: bucket mismatch for node %p",
__func__, __LINE__, cur_tln));
num_local_entries++;
}
INP_WUNLOCK(inp);
prev_tln = cur_tln;
}
KASSERT(tree_locked == TREE_UNLOCKED,
("%s: %d: tree unexpectedly locked", __func__, __LINE__));
switch (tree_locked) {
case TREE_WLOCKED:
TCPID_TREE_WUNLOCK();
tree_locked = TREE_UNLOCKED;
break;
case TREE_RLOCKED:
TCPID_TREE_RUNLOCK();
tree_locked = TREE_UNLOCKED;
break;
}
if (expireq_locked) {
TCPLOG_EXPIREQ_UNLOCK();
expireq_locked = false;
}
for (i = 0; i < num_local_entries; i++)
tcp_log_dump_node_logbuf(&local_entries[i], reason, M_WAITOK);
if (!tcp_log_unref_bucket(tlb, &tree_locked, NULL))
TCPID_BUCKET_UNLOCK(tlb);
done:
switch (tree_locked) {
case TREE_WLOCKED:
TCPID_TREE_WUNLOCK();
break;
case TREE_RLOCKED:
TCPID_TREE_RUNLOCK();
break;
}
if (expireq_locked)
TCPLOG_EXPIREQ_UNLOCK();
}
#undef LOCAL_SAVE
void
tcp_log_dump_tp_bucket_logbufs(struct tcpcb *tp, char *reason)
{
struct inpcb *inp = tptoinpcb(tp);
struct tcp_log_id_bucket *tlb;
int tree_locked;
INP_WLOCK_ASSERT(inp);
tlb = tp->t_lib;
if (tlb == NULL) {
(void)tcp_log_dump_tp_logbuf(tp, reason, M_WAITOK, true);
INP_WUNLOCK(inp);
return;
}
TCPID_BUCKET_REF(tlb);
INP_WUNLOCK(inp);
TCPID_BUCKET_LOCK(tlb);
tree_locked = TREE_UNLOCKED;
if (tcp_log_unref_bucket(tlb, &tree_locked, NULL)) {
switch (tree_locked) {
case TREE_WLOCKED:
TCPID_TREE_WUNLOCK();
break;
case TREE_RLOCKED:
TCPID_TREE_RUNLOCK();
break;
}
return;
}
tcp_log_dumpbucketlogs(tlb, reason);
}
void
tcp_log_flowend(struct tcpcb *tp)
{
if (tp->_t_logstate != TCP_LOG_STATE_OFF) {
struct socket *so = tptosocket(tp);
TCP_LOG_EVENT(tp, NULL, &so->so_rcv, &so->so_snd,
TCP_LOG_FLOWEND, 0, 0, NULL, false);
}
}
void
tcp_log_sendfile(struct socket *so, off_t offset, size_t nbytes, int flags)
{
struct inpcb *inp;
struct tcpcb *tp;
#ifdef TCP_REQUEST_TRK
struct tcp_sendfile_track *ent;
int i, fnd;
#endif
inp = sotoinpcb(so);
KASSERT(inp != NULL, ("tcp_log_sendfile: inp == NULL"));
tp = intotcpcb(inp);
if ((inp->inp_flags & INP_DROPPED) ||
(tp->_t_logstate == TCP_LOG_STATE_OFF)) {
return;
}
INP_WLOCK(inp);
if (inp->inp_flags & INP_DROPPED)
goto done;
if (tcp_bblogging_on(tp)) {
struct timeval tv;
tcp_log_eventspecific_t log;
memset(&log, 0, sizeof(log));
microuptime(&tv);
log.u_sf.offset = offset;
log.u_sf.length = nbytes;
log.u_sf.flags = flags;
TCP_LOG_EVENTP(tp, NULL,
&tptosocket(tp)->so_rcv,
&tptosocket(tp)->so_snd,
TCP_LOG_SENDFILE, 0, 0, &log, false, &tv);
}
#ifdef TCP_REQUEST_TRK
if (tp->t_tcpreq_req == 0) {
goto done;
}
fnd = 0;
if (tp->t_tcpreq_closed == 0) {
goto skip_closed_req;
}
for(i = 0; i < MAX_TCP_TRK_REQ; i++) {
ent = &tp->t_tcpreq_info[i];
if (ent->flags == TCP_TRK_TRACK_FLG_EMPTY) {
continue;
}
if (ent->flags & TCP_TRK_TRACK_FLG_OPEN) {
continue;
}
if (ent->flags & TCP_TRK_TRACK_FLG_COMP) {
continue;
}
if ((ent->start == offset) ||
((offset > ent->start) && (offset < ent->end))){
fnd = 1;
}
if (fnd) {
ent->flags |= TCP_TRK_TRACK_FLG_SEQV;
if (SEQ_GT((tp->snd_una + so->so_snd.sb_ccc), ent->end_seq))
ent->end_seq = tp->snd_una + so->so_snd.sb_ccc;
if ((offset + nbytes) >= ent->end) {
ent->flags |= TCP_TRK_TRACK_FLG_COMP;
tcp_req_log_req_info(tp, ent, i, TCP_TRK_REQ_LOG_COMPLETE, offset, nbytes);
} else {
tcp_req_log_req_info(tp, ent, i, TCP_TRK_REQ_LOG_MOREYET, offset, nbytes);
}
goto done;
}
}
skip_closed_req:
if (!fnd) {
for(i = 0; i < MAX_TCP_TRK_REQ; i++) {
ent = &tp->t_tcpreq_info[i];
if (ent->flags == TCP_TRK_TRACK_FLG_EMPTY) {
continue;
}
if ((ent->flags & TCP_TRK_TRACK_FLG_OPEN) == 0)
continue;
if (ent->start == offset) {
ent->start_seq = tp->snd_una +
tptosocket(tp)->so_snd.sb_ccc;
ent->flags |= TCP_TRK_TRACK_FLG_SEQV;
break;
} else if (offset > ent->start) {
ent->flags |= TCP_TRK_TRACK_FLG_SEQV;
break;
}
}
}
#endif
done:
INP_WUNLOCK(inp);
}
#ifdef DDB
static void
db_print_indent(int indent)
{
int i;
for (i = 0; i < indent; i++)
db_printf(" ");
}
static void
db_print_tcphdr(struct tcp_log_buffer *tlm_buf)
{
struct sackblk sack;
struct tcphdr *th;
int cnt, i, j, opt, optlen, num_sacks;
uint32_t val, ecr;
uint16_t mss;
uint16_t flags;
if ((tlm_buf->tlb_eventflags & TLB_FLAG_HDR) == 0) {
return;
}
th = &tlm_buf->tlb_th;
flags = tcp_get_flags(th);
if (flags & TH_FIN) {
db_printf("F");
}
if (flags & TH_SYN) {
db_printf("S");
}
if (flags & TH_RST) {
db_printf("R");
}
if (flags & TH_PUSH) {
db_printf("P");
}
if (flags & TH_ACK) {
db_printf(".");
}
if (flags & TH_URG) {
db_printf("U");
}
if (flags & TH_ECE) {
db_printf("E");
}
if (flags & TH_CWR) {
db_printf("W");
}
if (flags & TH_AE) {
db_printf("A");
}
db_printf(" %u:%u(%u)", ntohl(th->th_seq),
ntohl(th->th_seq) + tlm_buf->tlb_len, tlm_buf->tlb_len);
if (flags & TH_ACK) {
db_printf(" ack %u", ntohl(th->th_ack));
}
db_printf(" win %u", ntohs(th->th_win));
if (flags & TH_URG) {
db_printf(" urg %u", ntohs(th->th_urp));
}
cnt = (th->th_off << 2) - sizeof(struct tcphdr);
if (cnt > 0) {
db_printf(" <");
for (i = 0; i < cnt; i += optlen) {
opt = tlm_buf->tlb_opts[i];
if (opt == TCPOPT_EOL || opt == TCPOPT_NOP) {
optlen = 1;
} else {
if (cnt - i < 2) {
break;
}
optlen = tlm_buf->tlb_opts[i + 1];
if (optlen < 2 || optlen > cnt - i) {
break;
}
}
if (i > 0) {
db_printf(",");
}
switch (opt) {
case TCPOPT_EOL:
db_printf("eol");
break;
case TCPOPT_NOP:
db_printf("nop");
break;
case TCPOPT_MAXSEG:
if (optlen != TCPOLEN_MAXSEG) {
break;
}
bcopy(tlm_buf->tlb_opts + i + 2, &mss,
sizeof(uint16_t));
db_printf("mss %u", ntohs(mss));
break;
case TCPOPT_WINDOW:
if (optlen != TCPOLEN_WINDOW) {
break;
}
db_printf("wscale %u",
tlm_buf->tlb_opts[i + 2]);
break;
case TCPOPT_SACK_PERMITTED:
if (optlen != TCPOLEN_SACK_PERMITTED) {
break;
}
db_printf("sackOK");
break;
case TCPOPT_SACK:
if (optlen == TCPOLEN_SACKHDR ||
(optlen - 2) % TCPOLEN_SACK != 0) {
break;
}
num_sacks = (optlen - 2) / TCPOLEN_SACK;
db_printf("sack");
for (j = 0; j < num_sacks; j++) {
bcopy(tlm_buf->tlb_opts + i + 2 +
j * TCPOLEN_SACK, &sack,
TCPOLEN_SACK);
db_printf(" %u:%u", ntohl(sack.start),
ntohl(sack.end));
}
break;
case TCPOPT_TIMESTAMP:
if (optlen != TCPOLEN_TIMESTAMP) {
break;
}
bcopy(tlm_buf->tlb_opts + i + 2, &val,
sizeof(uint32_t));
bcopy(tlm_buf->tlb_opts + i + 6, &ecr,
sizeof(uint32_t));
db_printf("TS val %u ecr %u", ntohl(val),
ntohl(ecr));
break;
case TCPOPT_SIGNATURE:
db_printf("md5");
if (optlen > 2) {
db_printf(" ");
}
for (j = 0; j < optlen - 2; j++) {
db_printf("%02x",
tlm_buf->tlb_opts[i + 2 + j]);
}
break;
case TCPOPT_FAST_OPEN:
db_printf("FO");
if (optlen > 2) {
db_printf(" ");
}
for (j = 0; j < optlen - 2; j++) {
db_printf("%02x",
tlm_buf->tlb_opts[i + 2 + j]);
}
break;
default:
db_printf("opt=%u len=%u", opt, optlen);
break;
}
}
db_printf(">");
}
}
static void
db_print_pru(struct tcp_log_buffer *tlm_buf)
{
switch (tlm_buf->tlb_flex1) {
case PRU_ATTACH:
db_printf("ATTACH");
break;
case PRU_DETACH:
db_printf("DETACH");
break;
case PRU_BIND:
db_printf("BIND");
break;
case PRU_LISTEN:
db_printf("LISTEN");
break;
case PRU_CONNECT:
db_printf("CONNECT");
break;
case PRU_ACCEPT:
db_printf("ACCEPT");
break;
case PRU_DISCONNECT:
db_printf("DISCONNECT");
break;
case PRU_SHUTDOWN:
db_printf("SHUTDOWN");
break;
case PRU_RCVD:
db_printf("RCVD");
break;
case PRU_SEND:
db_printf("SEND");
break;
case PRU_ABORT:
db_printf("ABORT");
break;
case PRU_CONTROL:
db_printf("CONTROL");
break;
case PRU_SENSE:
db_printf("SENSE");
break;
case PRU_RCVOOB:
db_printf("RCVOOB");
break;
case PRU_SENDOOB:
db_printf("SENDOOB");
break;
case PRU_SOCKADDR:
db_printf("SOCKADDR");
break;
case PRU_PEERADDR:
db_printf("PEERADDR");
break;
case PRU_CONNECT2:
db_printf("CONNECT2");
break;
case PRU_FASTTIMO:
db_printf("FASTTIMO");
break;
case PRU_SLOWTIMO:
db_printf("SLOWTIMO");
break;
case PRU_PROTORCV:
db_printf("PROTORCV");
break;
case PRU_PROTOSEND:
db_printf("PROTOSEND");
break;
case PRU_SEND_EOF:
db_printf("SEND_EOF");
break;
case PRU_SOSETLABEL:
db_printf("SOSETLABEL");
break;
case PRU_CLOSE:
db_printf("CLOSE");
break;
case PRU_FLUSH:
db_printf("FLUSH");
break;
default:
db_printf("Unknown PRU (%u)", tlm_buf->tlb_flex1);
break;
}
if (tlm_buf->tlb_errno >= 0) {
db_printf(", error: %d", tlm_buf->tlb_errno);
}
}
static void
db_print_rto(struct tcp_log_buffer *tlm_buf)
{
tt_what what;
tt_which which;
what = (tlm_buf->tlb_flex1 & 0xffffff00) >> 8;
which = tlm_buf->tlb_flex1 & 0x000000ff;
switch (what) {
case TT_PROCESSING:
db_printf("Processing ");
break;
case TT_PROCESSED:
db_printf("Processed ");
break;
case TT_STARTING:
db_printf("Starting ");
break;
case TT_STOPPING:
db_printf("Stopping ");
break;
default:
db_printf("Unknown operation (%u) for ", what);
break;
}
switch (which) {
case TT_REXMT:
db_printf("Retransmission ");
break;
case TT_PERSIST:
db_printf("Persist ");
break;
case TT_KEEP:
db_printf("Keepalive ");
break;
case TT_2MSL:
db_printf("2 MSL ");
break;
case TT_DELACK:
db_printf("Delayed ACK ");
break;
default:
db_printf("Unknown (%u) ", which);
break;
}
db_printf("timer");
if (what == TT_STARTING) {
db_printf(": %u ms", tlm_buf->tlb_flex2);
}
}
static void
db_print_usersend(struct tcp_log_buffer *tlm_buf)
{
if ((tlm_buf->tlb_eventflags & TLB_FLAG_RXBUF) == 0) {
return;
}
if ((tlm_buf->tlb_eventflags & TLB_FLAG_TXBUF) == 0) {
return;
}
db_printf("usersend: rcv.acc: %u rcv.ccc: %u snd.acc: %u snd.ccc: %u",
tlm_buf->tlb_rxbuf.tls_sb_acc, tlm_buf->tlb_rxbuf.tls_sb_ccc,
tlm_buf->tlb_txbuf.tls_sb_acc, tlm_buf->tlb_txbuf.tls_sb_ccc);
}
void
db_print_bblog_entries(struct tcp_log_stailq *log_entries, int indent)
{
struct tcp_log_mem *log_entry;
struct tcp_log_buffer *tlm_buf, *prev_tlm_buf;
int64_t delta_t;
indent += 2;
prev_tlm_buf = NULL;
STAILQ_FOREACH(log_entry, log_entries, tlm_queue) {
db_print_indent(indent);
tlm_buf = &log_entry->tlm_buf;
if (prev_tlm_buf == NULL) {
db_printf(" 0.000 ");
} else {
delta_t = sbttoms(tvtosbt(tlm_buf->tlb_tv) -
tvtosbt(prev_tlm_buf->tlb_tv));
db_printf("+%u.%03u ", (uint32_t)(delta_t / 1000),
(uint32_t)(delta_t % 1000));
}
switch (tlm_buf->tlb_eventid) {
case TCP_LOG_IN:
db_printf("< ");
db_print_tcphdr(tlm_buf);
break;
case TCP_LOG_OUT:
db_printf("> ");
db_print_tcphdr(tlm_buf);
break;
case TCP_LOG_RTO:
db_print_rto(tlm_buf);
break;
case TCP_LOG_PRU:
db_print_pru(tlm_buf);
break;
case TCP_LOG_USERSEND:
db_print_usersend(tlm_buf);
break;
default:
break;
}
db_printf("\n");
prev_tlm_buf = tlm_buf;
if (db_pager_quit)
break;
}
}
#endif