1
2 /*-
3 * SPDX-License-Identifier: BSD-2-Clause
4 *
5 * Copyright (c) 2016-2018 Netflix, Inc.
6 *
7 * Redistribution and use in source and binary forms, with or without
8 * modification, are permitted provided that the following conditions
9 * are met:
10 * 1. Redistributions of source code must retain the above copyright
11 * notice, this list of conditions and the following disclaimer.
12 * 2. Redistributions in binary form must reproduce the above copyright
13 * notice, this list of conditions and the following disclaimer in the
14 * documentation and/or other materials provided with the distribution.
15 *
16 * THIS SOFTWARE IS PROVIDED BY THE AUTHOR AND CONTRIBUTORS ``AS IS'' AND
17 * ANY EXPRESS OR IMPLIED WARRANTIES, INCLUDING, BUT NOT LIMITED TO, THE
18 * IMPLIED WARRANTIES OF MERCHANTABILITY AND FITNESS FOR A PARTICULAR PURPOSE
19 * ARE DISCLAIMED. IN NO EVENT SHALL THE AUTHOR OR CONTRIBUTORS BE LIABLE
20 * FOR ANY DIRECT, INDIRECT, INCIDENTAL, SPECIAL, EXEMPLARY, OR CONSEQUENTIAL
21 * DAMAGES (INCLUDING, BUT NOT LIMITED TO, PROCUREMENT OF SUBSTITUTE GOODS
22 * OR SERVICES; LOSS OF USE, DATA, OR PROFITS; OR BUSINESS INTERRUPTION)
23 * HOWEVER CAUSED AND ON ANY THEORY OF LIABILITY, WHETHER IN CONTRACT, STRICT
24 * LIABILITY, OR TORT (INCLUDING NEGLIGENCE OR OTHERWISE) ARISING IN ANY WAY
25 * OUT OF THE USE OF THIS SOFTWARE, EVEN IF ADVISED OF THE POSSIBILITY OF
26 * SUCH DAMAGE.
27 *
28 */
29
30 #include <sys/cdefs.h>
31 #include "opt_inet.h"
32 #include "opt_ddb.h"
33 #include <sys/param.h>
34 #include <sys/arb.h>
35 #include <sys/hash.h>
36 #include <sys/kernel.h>
37 #include <sys/lock.h>
38 #include <sys/malloc.h>
39 #include <sys/mutex.h>
40 #include <sys/qmath.h>
41 #include <sys/queue.h>
42 #include <sys/refcount.h>
43 #include <sys/rwlock.h>
44 #include <sys/socket.h>
45 #include <sys/socketvar.h>
46 #include <sys/sysctl.h>
47 #ifdef DDB
48 #include <sys/time.h>
49 #endif
50 #include <sys/tree.h>
51 #include <sys/stats.h> /* Must come after qmath.h and tree.h */
52 #include <sys/counter.h>
53 #include <dev/tcp_log/tcp_log_dev.h>
54
55 #ifdef DDB
56 #include <ddb/ddb.h>
57 #endif
58
59 #include <net/if.h>
60 #include <net/if_var.h>
61 #include <net/vnet.h>
62
63 #include <netinet/in.h>
64 #ifdef DDB
65 #include <netinet/in_kdtrace.h>
66 #endif
67 #include <netinet/in_pcb.h>
68 #include <netinet/in_var.h>
69 #include <netinet/tcp_var.h>
70 #include <netinet/tcp_log_buf.h>
71 #include <netinet/tcp_seq.h>
72 #include <netinet/tcp_hpts.h>
73
74 /* Default expiry time */
75 #define TCP_LOG_EXPIRE_TIME ((sbintime_t)60 * SBT_1S)
76
77 /* Max interval at which to run the expiry timer */
78 #define TCP_LOG_EXPIRE_INTVL ((sbintime_t)5 * SBT_1S)
79
80 bool tcp_log_verbose;
81 static uma_zone_t tcp_log_id_bucket_zone, tcp_log_id_node_zone, tcp_log_zone;
82 static int tcp_log_session_limit = TCP_LOG_BUF_DEFAULT_SESSION_LIMIT;
83 static uint32_t tcp_log_version = TCP_LOG_BUF_VER;
84 RB_HEAD(tcp_log_id_tree, tcp_log_id_bucket);
85 static struct tcp_log_id_tree tcp_log_id_head;
86 static STAILQ_HEAD(, tcp_log_id_node) tcp_log_expireq_head =
87 STAILQ_HEAD_INITIALIZER(tcp_log_expireq_head);
88 static struct mtx tcp_log_expireq_mtx;
89 static struct callout tcp_log_expireq_callout;
90 static u_long tcp_log_auto_ratio = 0;
91 static volatile u_long tcp_log_auto_ratio_cur = 0;
92 static uint32_t tcp_log_auto_mode = TCP_LOG_STATE_TAIL;
93 static bool tcp_log_auto_all = false;
94 static uint32_t tcp_disable_all_bb_logs = 0;
95
96 RB_PROTOTYPE_STATIC(tcp_log_id_tree, tcp_log_id_bucket, tlb_rb, tcp_log_id_cmp)
97
98 SYSCTL_NODE(_net_inet_tcp, OID_AUTO, bb, CTLFLAG_RW | CTLFLAG_MPSAFE, 0,
99 "TCP Black Box controls");
100
101 SYSCTL_NODE(_net_inet_tcp_bb, OID_AUTO, tp, CTLFLAG_RW | CTLFLAG_MPSAFE, 0,
102 "TCP Black Box Trace Point controls");
103
104 SYSCTL_BOOL(_net_inet_tcp_bb, OID_AUTO, log_verbose, CTLFLAG_RW, &tcp_log_verbose,
105 0, "Force verbose logging for TCP traces");
106
107 SYSCTL_INT(_net_inet_tcp_bb, OID_AUTO, log_session_limit,
108 CTLFLAG_RW, &tcp_log_session_limit, 0,
109 "Maximum number of events maintained for each TCP session");
110
111 uint32_t tcp_trace_point_config = 0;
112 SYSCTL_U32(_net_inet_tcp_bb_tp, OID_AUTO, number, CTLFLAG_RW,
113 &tcp_trace_point_config, TCP_LOG_STATE_HEAD_AUTO,
114 "What is the trace point number to activate (0=none, 0xffffffff = all)?");
115
116 uint32_t tcp_trace_point_bb_mode = TCP_LOG_STATE_CONTINUAL;
117 SYSCTL_U32(_net_inet_tcp_bb_tp, OID_AUTO, bbmode, CTLFLAG_RW,
118 &tcp_trace_point_bb_mode, TCP_LOG_STATE_HEAD_AUTO,
119 "What is BB logging mode that is activated?");
120
121 int32_t tcp_trace_point_count = 0;
122 SYSCTL_U32(_net_inet_tcp_bb_tp, OID_AUTO, count, CTLFLAG_RW,
123 &tcp_trace_point_count, TCP_LOG_STATE_HEAD_AUTO,
124 "How many connections will have BB logging turned on that hit the tracepoint?");
125
126
127
128 SYSCTL_UMA_MAX(_net_inet_tcp_bb, OID_AUTO, log_global_limit, CTLFLAG_RW,
129 &tcp_log_zone, "Maximum number of events maintained for all TCP sessions");
130
131 SYSCTL_UMA_CUR(_net_inet_tcp_bb, OID_AUTO, log_global_entries, CTLFLAG_RD,
132 &tcp_log_zone, "Current number of events maintained for all TCP sessions");
133
134 SYSCTL_UMA_MAX(_net_inet_tcp_bb, OID_AUTO, log_id_limit, CTLFLAG_RW,
135 &tcp_log_id_bucket_zone, "Maximum number of log IDs");
136
137 SYSCTL_UMA_CUR(_net_inet_tcp_bb, OID_AUTO, log_id_entries, CTLFLAG_RD,
138 &tcp_log_id_bucket_zone, "Current number of log IDs");
139
140 SYSCTL_UMA_MAX(_net_inet_tcp_bb, OID_AUTO, log_id_tcpcb_limit, CTLFLAG_RW,
141 &tcp_log_id_node_zone, "Maximum number of tcpcbs with log IDs");
142
143 SYSCTL_UMA_CUR(_net_inet_tcp_bb, OID_AUTO, log_id_tcpcb_entries, CTLFLAG_RD,
144 &tcp_log_id_node_zone, "Current number of tcpcbs with log IDs");
145
146 SYSCTL_U32(_net_inet_tcp_bb, OID_AUTO, log_version, CTLFLAG_RD, &tcp_log_version,
147 0, "Version of log formats exported");
148
149 SYSCTL_U32(_net_inet_tcp_bb, OID_AUTO, disable_all, CTLFLAG_RW,
150 &tcp_disable_all_bb_logs, 0,
151 "Disable all BB logging for all connections");
152
153 SYSCTL_ULONG(_net_inet_tcp_bb, OID_AUTO, log_auto_ratio, CTLFLAG_RW,
154 &tcp_log_auto_ratio, 0, "Do auto capturing for 1 out of N sessions");
155
156 SYSCTL_U32(_net_inet_tcp_bb, OID_AUTO, log_auto_mode, CTLFLAG_RW,
157 &tcp_log_auto_mode, 0,
158 "Logging mode for auto-selected sessions (default is TCP_LOG_STATE_TAIL)");
159
160 SYSCTL_BOOL(_net_inet_tcp_bb, OID_AUTO, log_auto_all, CTLFLAG_RW,
161 &tcp_log_auto_all, 0,
162 "Auto-select from all sessions (rather than just those with IDs)");
163
164 #ifdef TCPLOG_DEBUG_COUNTERS
165 counter_u64_t tcp_log_queued;
166 counter_u64_t tcp_log_que_fail1;
167 counter_u64_t tcp_log_que_fail2;
168 counter_u64_t tcp_log_que_fail3;
169 counter_u64_t tcp_log_que_fail4;
170 counter_u64_t tcp_log_que_fail5;
171 counter_u64_t tcp_log_que_copyout;
172 counter_u64_t tcp_log_que_read;
173 counter_u64_t tcp_log_que_freed;
174
175 SYSCTL_COUNTER_U64(_net_inet_tcp_bb, OID_AUTO, queued, CTLFLAG_RD,
176 &tcp_log_queued, "Number of entries queued");
177 SYSCTL_COUNTER_U64(_net_inet_tcp_bb, OID_AUTO, fail1, CTLFLAG_RD,
178 &tcp_log_que_fail1, "Number of entries queued but fail 1");
179 SYSCTL_COUNTER_U64(_net_inet_tcp_bb, OID_AUTO, fail2, CTLFLAG_RD,
180 &tcp_log_que_fail2, "Number of entries queued but fail 2");
181 SYSCTL_COUNTER_U64(_net_inet_tcp_bb, OID_AUTO, fail3, CTLFLAG_RD,
182 &tcp_log_que_fail3, "Number of entries queued but fail 3");
183 SYSCTL_COUNTER_U64(_net_inet_tcp_bb, OID_AUTO, fail4, CTLFLAG_RD,
184 &tcp_log_que_fail4, "Number of entries queued but fail 4");
185 SYSCTL_COUNTER_U64(_net_inet_tcp_bb, OID_AUTO, fail5, CTLFLAG_RD,
186 &tcp_log_que_fail5, "Number of entries queued but fail 4");
187 SYSCTL_COUNTER_U64(_net_inet_tcp_bb, OID_AUTO, copyout, CTLFLAG_RD,
188 &tcp_log_que_copyout, "Number of entries copied out");
189 SYSCTL_COUNTER_U64(_net_inet_tcp_bb, OID_AUTO, read, CTLFLAG_RD,
190 &tcp_log_que_read, "Number of entries read from the queue");
191 SYSCTL_COUNTER_U64(_net_inet_tcp_bb, OID_AUTO, freed, CTLFLAG_RD,
192 &tcp_log_que_freed, "Number of entries freed after reading");
193 #endif
194
195 #ifdef INVARIANTS
196 #define TCPLOG_DEBUG_RINGBUF
197 #endif
198 /* Number of requests to consider a PBCID "active". */
199 #define ACTIVE_REQUEST_COUNT 10
200
201 /* Statistic tracking for "active" PBCIDs. */
202 static counter_u64_t tcp_log_pcb_ids_cur;
203 static counter_u64_t tcp_log_pcb_ids_tot;
204
205 SYSCTL_COUNTER_U64(_net_inet_tcp_bb, OID_AUTO, pcb_ids_cur, CTLFLAG_RD,
206 &tcp_log_pcb_ids_cur, "Number of pcb IDs allocated in the system");
207 SYSCTL_COUNTER_U64(_net_inet_tcp_bb, OID_AUTO, pcb_ids_tot, CTLFLAG_RD,
208 &tcp_log_pcb_ids_tot, "Total number of pcb IDs that have been allocated");
209
210 struct tcp_log_mem
211 {
212 STAILQ_ENTRY(tcp_log_mem) tlm_queue;
213 struct tcp_log_buffer tlm_buf;
214 struct tcp_log_verbose tlm_v;
215 #ifdef TCPLOG_DEBUG_RINGBUF
216 volatile int tlm_refcnt;
217 #endif
218 };
219
220 /* 60 bytes for the header, + 16 bytes for padding */
221 static uint8_t zerobuf[76];
222
223 /*
224 * Lock order:
225 * 1. TCPID_TREE
226 * 2. TCPID_BUCKET
227 * 3. INP
228 *
229 * Rules:
230 * A. You need a lock on the Tree to add/remove buckets.
231 * B. You need a lock on the bucket to add/remove nodes from the bucket.
232 * C. To change information in a node, you need the INP lock if the tln_closed
233 * field is false. Otherwise, you need the bucket lock. (Note that the
234 * tln_closed field can change at any point, so you need to recheck the
235 * entry after acquiring the INP lock.)
236 * D. To remove a node from the bucket, you must have that entry locked,
237 * according to the criteria of Rule C. Also, the node must not be on
238 * the expiry queue.
239 * E. The exception to C is the expiry queue fields, which are locked by
240 * the TCPLOG_EXPIREQ lock.
241 *
242 * Buckets have a reference count. Each node is a reference. Further,
243 * other callers may add reference counts to keep a bucket from disappearing.
244 * You can add a reference as long as you own a lock sufficient to keep the
245 * bucket from disappearing. For example, a common use is:
246 * a. Have a locked INP, but need to lock the TCPID_BUCKET.
247 * b. Add a refcount on the bucket. (Safe because the INP lock prevents
248 * the TCPID_BUCKET from going away.)
249 * c. Drop the INP lock.
250 * d. Acquire a lock on the TCPID_BUCKET.
251 * e. Acquire a lock on the INP.
252 * f. Drop the refcount on the bucket.
253 * (At this point, the bucket may disappear.)
254 *
255 * Expire queue lock:
256 * You can acquire this with either the bucket or INP lock. Don't reverse it.
257 * When the expire code has committed to freeing a node, it resets the expiry
258 * time to SBT_MAX. That is the signal to everyone else that they should
259 * leave that node alone.
260 */
261 static struct rwlock tcp_id_tree_lock;
262 #define TCPID_TREE_WLOCK() rw_wlock(&tcp_id_tree_lock)
263 #define TCPID_TREE_RLOCK() rw_rlock(&tcp_id_tree_lock)
264 #define TCPID_TREE_UPGRADE() rw_try_upgrade(&tcp_id_tree_lock)
265 #define TCPID_TREE_WUNLOCK() rw_wunlock(&tcp_id_tree_lock)
266 #define TCPID_TREE_RUNLOCK() rw_runlock(&tcp_id_tree_lock)
267 #define TCPID_TREE_WLOCK_ASSERT() rw_assert(&tcp_id_tree_lock, RA_WLOCKED)
268 #define TCPID_TREE_RLOCK_ASSERT() rw_assert(&tcp_id_tree_lock, RA_RLOCKED)
269 #define TCPID_TREE_UNLOCK_ASSERT() rw_assert(&tcp_id_tree_lock, RA_UNLOCKED)
270
271 #define TCPID_BUCKET_LOCK_INIT(tlb) mtx_init(&((tlb)->tlb_mtx), "tcp log id bucket", NULL, MTX_DEF)
272 #define TCPID_BUCKET_LOCK_DESTROY(tlb) mtx_destroy(&((tlb)->tlb_mtx))
273 #define TCPID_BUCKET_LOCK(tlb) mtx_lock(&((tlb)->tlb_mtx))
274 #define TCPID_BUCKET_UNLOCK(tlb) mtx_unlock(&((tlb)->tlb_mtx))
275 #define TCPID_BUCKET_LOCK_ASSERT(tlb) mtx_assert(&((tlb)->tlb_mtx), MA_OWNED)
276 #define TCPID_BUCKET_UNLOCK_ASSERT(tlb) mtx_assert(&((tlb)->tlb_mtx), MA_NOTOWNED)
277
278 #define TCPID_BUCKET_REF(tlb) refcount_acquire(&((tlb)->tlb_refcnt))
279 #define TCPID_BUCKET_UNREF(tlb) refcount_release(&((tlb)->tlb_refcnt))
280
281 #define TCPLOG_EXPIREQ_LOCK() mtx_lock(&tcp_log_expireq_mtx)
282 #define TCPLOG_EXPIREQ_UNLOCK() mtx_unlock(&tcp_log_expireq_mtx)
283
284 SLIST_HEAD(tcp_log_id_head, tcp_log_id_node);
285
286 struct tcp_log_id_bucket
287 {
288 /*
289 * tlb_id must be first. This lets us use strcmp on
290 * (struct tcp_log_id_bucket *) and (char *) interchangeably.
291 */
292 char tlb_id[TCP_LOG_ID_LEN];
293 char tlb_tag[TCP_LOG_TAG_LEN];
294 RB_ENTRY(tcp_log_id_bucket) tlb_rb;
295 struct tcp_log_id_head tlb_head;
296 struct mtx tlb_mtx;
297 volatile u_int tlb_refcnt;
298 volatile u_int tlb_reqcnt;
299 uint32_t tlb_loglimit;
300 int8_t tlb_logstate;
301 };
302
303 struct tcp_log_id_node
304 {
305 SLIST_ENTRY(tcp_log_id_node) tln_list;
306 STAILQ_ENTRY(tcp_log_id_node) tln_expireq; /* Locked by the expireq lock */
307 sbintime_t tln_expiretime; /* Locked by the expireq lock */
308
309 /*
310 * If INP is NULL, that means the connection has closed. We've
311 * saved the connection endpoint information and the log entries
312 * in the tln_ie and tln_entries members. We've also saved a pointer
313 * to the enclosing bucket here. If INP is not NULL, the information is
314 * in the PCB and not here.
315 */
316 struct inpcb *tln_inp;
317 struct tcpcb *tln_tp;
318 struct tcp_log_id_bucket *tln_bucket;
319 struct in_endpoints tln_ie;
320 struct tcp_log_stailq tln_entries;
321 int tln_count;
322 volatile int tln_closed;
323 uint8_t tln_af;
324 };
325
326 enum tree_lock_state {
327 TREE_UNLOCKED = 0,
328 TREE_RLOCKED,
329 TREE_WLOCKED,
330 };
331
332 /* Do we want to select this session for auto-logging? */
333 static __inline bool
tcp_log_selectauto(void)334 tcp_log_selectauto(void)
335 {
336
337 /*
338 * If we are doing auto-capturing, figure out whether we will capture
339 * this session.
340 */
341 if (tcp_log_auto_ratio &&
342 (tcp_disable_all_bb_logs == 0) &&
343 (atomic_fetchadd_long(&tcp_log_auto_ratio_cur, 1) %
344 tcp_log_auto_ratio) == 0)
345 return (true);
346 return (false);
347 }
348
349 static __inline int
tcp_log_id_cmp(struct tcp_log_id_bucket * a,struct tcp_log_id_bucket * b)350 tcp_log_id_cmp(struct tcp_log_id_bucket *a, struct tcp_log_id_bucket *b)
351 {
352 KASSERT(a != NULL, ("tcp_log_id_cmp: argument a is unexpectedly NULL"));
353 KASSERT(b != NULL, ("tcp_log_id_cmp: argument b is unexpectedly NULL"));
354 return strncmp(a->tlb_id, b->tlb_id, TCP_LOG_ID_LEN);
355 }
356
RB_GENERATE_STATIC(tcp_log_id_tree,tcp_log_id_bucket,tlb_rb,tcp_log_id_cmp)357 RB_GENERATE_STATIC(tcp_log_id_tree, tcp_log_id_bucket, tlb_rb, tcp_log_id_cmp)
358
359 static __inline void
360 tcp_log_id_validate_tree_lock(int tree_locked)
361 {
362
363 #ifdef INVARIANTS
364 switch (tree_locked) {
365 case TREE_WLOCKED:
366 TCPID_TREE_WLOCK_ASSERT();
367 break;
368 case TREE_RLOCKED:
369 TCPID_TREE_RLOCK_ASSERT();
370 break;
371 case TREE_UNLOCKED:
372 TCPID_TREE_UNLOCK_ASSERT();
373 break;
374 default:
375 kassert_panic("%s:%d: unknown tree lock state", __func__,
376 __LINE__);
377 }
378 #endif
379 }
380
381 static __inline void
tcp_log_remove_bucket(struct tcp_log_id_bucket * tlb)382 tcp_log_remove_bucket(struct tcp_log_id_bucket *tlb)
383 {
384
385 TCPID_TREE_WLOCK_ASSERT();
386 KASSERT(SLIST_EMPTY(&tlb->tlb_head),
387 ("%s: Attempt to remove non-empty bucket", __func__));
388 if (RB_REMOVE(tcp_log_id_tree, &tcp_log_id_head, tlb) == NULL) {
389 #ifdef INVARIANTS
390 kassert_panic("%s:%d: error removing element from tree",
391 __func__, __LINE__);
392 #endif
393 }
394 TCPID_BUCKET_LOCK_DESTROY(tlb);
395 counter_u64_add(tcp_log_pcb_ids_cur, (int64_t)-1);
396 uma_zfree(tcp_log_id_bucket_zone, tlb);
397 }
398
399 /*
400 * Call with a referenced and locked bucket.
401 * Will return true if the bucket was freed; otherwise, false.
402 * tlb: The bucket to unreference.
403 * tree_locked: A pointer to the state of the tree lock. If the tree lock
404 * state changes, the function will update it.
405 * inp: If not NULL and the function needs to drop the inp lock to relock the
406 * tree, it will do so. (The caller must ensure inp will not become invalid,
407 * probably by holding a reference to it.)
408 */
409 static bool
tcp_log_unref_bucket(struct tcp_log_id_bucket * tlb,int * tree_locked,struct inpcb * inp)410 tcp_log_unref_bucket(struct tcp_log_id_bucket *tlb, int *tree_locked,
411 struct inpcb *inp)
412 {
413
414 KASSERT(tlb != NULL, ("%s: called with NULL tlb", __func__));
415 KASSERT(tree_locked != NULL, ("%s: called with NULL tree_locked",
416 __func__));
417
418 tcp_log_id_validate_tree_lock(*tree_locked);
419
420 /*
421 * Did we hold the last reference on the tlb? If so, we may need
422 * to free it. (Note that we can realistically only execute the
423 * loop twice: once without a write lock and once with a write
424 * lock.)
425 */
426 while (TCPID_BUCKET_UNREF(tlb)) {
427 /*
428 * We need a write lock on the tree to free this.
429 * If we can upgrade the tree lock, this is "easy". If we
430 * can't upgrade the tree lock, we need to do this the
431 * "hard" way: unwind all our locks and relock everything.
432 * In the meantime, anything could have changed. We even
433 * need to validate that we still need to free the bucket.
434 */
435 if (*tree_locked == TREE_RLOCKED && TCPID_TREE_UPGRADE())
436 *tree_locked = TREE_WLOCKED;
437 else if (*tree_locked != TREE_WLOCKED) {
438 TCPID_BUCKET_REF(tlb);
439 if (inp != NULL)
440 INP_WUNLOCK(inp);
441 TCPID_BUCKET_UNLOCK(tlb);
442 if (*tree_locked == TREE_RLOCKED)
443 TCPID_TREE_RUNLOCK();
444 TCPID_TREE_WLOCK();
445 *tree_locked = TREE_WLOCKED;
446 TCPID_BUCKET_LOCK(tlb);
447 if (inp != NULL)
448 INP_WLOCK(inp);
449 continue;
450 }
451
452 /*
453 * We have an empty bucket and a write lock on the tree.
454 * Remove the empty bucket.
455 */
456 tcp_log_remove_bucket(tlb);
457 return (true);
458 }
459 return (false);
460 }
461
462 /*
463 * Call with a locked bucket. This function will release the lock on the
464 * bucket before returning.
465 *
466 * The caller is responsible for freeing the tp->t_lin/tln node!
467 *
468 * Note: one of tp or both tlb and tln must be supplied.
469 *
470 * inp: A pointer to the inp. If the function needs to drop the inp lock to
471 * acquire the tree write lock, it will do so. (The caller must ensure inp
472 * will not become invalid, probably by holding a reference to it.)
473 * tp: A pointer to the tcpcb. (optional; if specified, tlb and tln are ignored)
474 * tlb: A pointer to the bucket. (optional; ignored if tp is specified)
475 * tln: A pointer to the node. (optional; ignored if tp is specified)
476 * tree_locked: A pointer to the state of the tree lock. If the tree lock
477 * state changes, the function will update it.
478 *
479 * Will return true if the INP lock was reacquired; otherwise, false.
480 */
481 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)482 tcp_log_remove_id_node(struct inpcb *inp, struct tcpcb *tp,
483 struct tcp_log_id_bucket *tlb, struct tcp_log_id_node *tln,
484 int *tree_locked)
485 {
486 int orig_tree_locked;
487
488 KASSERT(tp != NULL || (tlb != NULL && tln != NULL),
489 ("%s: called with tp=%p, tlb=%p, tln=%p", __func__,
490 tp, tlb, tln));
491 KASSERT(tree_locked != NULL, ("%s: called with NULL tree_locked",
492 __func__));
493
494 if (tp != NULL) {
495 tlb = tp->t_lib;
496 tln = tp->t_lin;
497 KASSERT(tlb != NULL, ("%s: unexpectedly NULL tlb", __func__));
498 KASSERT(tln != NULL, ("%s: unexpectedly NULL tln", __func__));
499 }
500
501 tcp_log_id_validate_tree_lock(*tree_locked);
502 TCPID_BUCKET_LOCK_ASSERT(tlb);
503
504 /*
505 * Remove the node, clear the log bucket and node from the TCPCB, and
506 * decrement the bucket refcount. In the process, if this is the
507 * last reference, the bucket will be freed.
508 */
509 SLIST_REMOVE(&tlb->tlb_head, tln, tcp_log_id_node, tln_list);
510 if (tp != NULL) {
511 tp->t_lib = NULL;
512 tp->t_lin = NULL;
513 }
514 orig_tree_locked = *tree_locked;
515 if (!tcp_log_unref_bucket(tlb, tree_locked, inp))
516 TCPID_BUCKET_UNLOCK(tlb);
517 return (*tree_locked != orig_tree_locked);
518 }
519
520 #define RECHECK_INP_CLEAN(cleanup) do { \
521 if (inp->inp_flags & INP_DROPPED) { \
522 rv = ECONNRESET; \
523 cleanup; \
524 goto done; \
525 } \
526 tp = intotcpcb(inp); \
527 } while (0)
528
529 #define RECHECK_INP() RECHECK_INP_CLEAN(/* noop */)
530
531 static void
tcp_log_grow_tlb(char * tlb_id,struct tcpcb * tp)532 tcp_log_grow_tlb(char *tlb_id, struct tcpcb *tp)
533 {
534
535 INP_WLOCK_ASSERT(tptoinpcb(tp));
536
537 #ifdef STATS
538 if (V_tcp_perconn_stats_enable == 2 && tp->t_stats == NULL)
539 (void)tcp_stats_sample_rollthedice(tp, tlb_id, strlen(tlb_id));
540 #endif
541 }
542
543 static void
tcp_log_increment_reqcnt(struct tcp_log_id_bucket * tlb)544 tcp_log_increment_reqcnt(struct tcp_log_id_bucket *tlb)
545 {
546
547 atomic_fetchadd_int(&tlb->tlb_reqcnt, 1);
548 }
549
550 int
tcp_log_apply_ratio(struct tcpcb * tp,int ratio)551 tcp_log_apply_ratio(struct tcpcb *tp, int ratio)
552 {
553 struct tcp_log_id_bucket *tlb;
554 struct inpcb *inp = tptoinpcb(tp);
555 uint32_t hash, ratio_hash_thresh;
556 int rv, tree_locked;
557
558 rv = 0;
559 tree_locked = TREE_UNLOCKED;
560 tlb = tp->t_lib;
561
562 INP_WLOCK_ASSERT(inp);
563 if (tlb == NULL) {
564 INP_WUNLOCK(inp);
565 return (EOPNOTSUPP);
566 }
567 if (ratio)
568 ratio_hash_thresh = max(1, UINT32_MAX / ratio);
569 else
570 ratio_hash_thresh = 0;
571 TCPID_BUCKET_REF(tlb);
572 INP_WUNLOCK(inp);
573 TCPID_BUCKET_LOCK(tlb);
574
575 hash = hash32_buf(tlb->tlb_id, strlen(tlb->tlb_id), 0);
576 if (hash > ratio_hash_thresh && tp->_t_logstate == TCP_LOG_STATE_OFF &&
577 tlb->tlb_logstate == TCP_LOG_STATE_OFF) {
578 /*
579 * Ratio decision not to log this log ID (and this connection by
580 * way of association). We only apply a log ratio log disable
581 * decision if it would not interfere with a log enable decision
582 * made elsewhere e.g. tcp_log_selectauto() or setsockopt().
583 */
584 tlb->tlb_logstate = TCP_LOG_STATE_RATIO_OFF;
585 INP_WLOCK(inp);
586 RECHECK_INP();
587 (void)tcp_log_state_change(tp, TCP_LOG_STATE_OFF);
588 done:
589 INP_WUNLOCK(inp);
590 }
591
592 INP_UNLOCK_ASSERT(inp);
593 if (!tcp_log_unref_bucket(tlb, &tree_locked, NULL))
594 TCPID_BUCKET_UNLOCK(tlb);
595
596 if (tree_locked == TREE_WLOCKED) {
597 TCPID_TREE_WLOCK_ASSERT();
598 TCPID_TREE_WUNLOCK();
599 } else if (tree_locked == TREE_RLOCKED) {
600 TCPID_TREE_RLOCK_ASSERT();
601 TCPID_TREE_RUNLOCK();
602 } else
603 TCPID_TREE_UNLOCK_ASSERT();
604
605 return (rv);
606 }
607
608 /*
609 * Associate the specified tag with a particular TCP log ID.
610 * Called with INPCB locked. Returns with it unlocked.
611 * Returns 0 on success or EOPNOTSUPP if the connection has no TCP log ID.
612 */
613 int
tcp_log_set_tag(struct tcpcb * tp,char * tag)614 tcp_log_set_tag(struct tcpcb *tp, char *tag)
615 {
616 struct inpcb *inp = tptoinpcb(tp);
617 struct tcp_log_id_bucket *tlb;
618 int tree_locked;
619
620 INP_WLOCK_ASSERT(inp);
621
622 tree_locked = TREE_UNLOCKED;
623 tlb = tp->t_lib;
624 if (tlb == NULL) {
625 INP_WUNLOCK(inp);
626 return (EOPNOTSUPP);
627 }
628
629 TCPID_BUCKET_REF(tlb);
630 INP_WUNLOCK(inp);
631 TCPID_BUCKET_LOCK(tlb);
632 strlcpy(tlb->tlb_tag, tag, TCP_LOG_TAG_LEN);
633 if (!tcp_log_unref_bucket(tlb, &tree_locked, NULL))
634 TCPID_BUCKET_UNLOCK(tlb);
635
636 if (tree_locked == TREE_WLOCKED) {
637 TCPID_TREE_WLOCK_ASSERT();
638 TCPID_TREE_WUNLOCK();
639 } else if (tree_locked == TREE_RLOCKED) {
640 TCPID_TREE_RLOCK_ASSERT();
641 TCPID_TREE_RUNLOCK();
642 } else
643 TCPID_TREE_UNLOCK_ASSERT();
644
645 return (0);
646 }
647
648 /*
649 * Set the TCP log ID for a TCPCB.
650 * Called with INPCB locked. Returns with it unlocked.
651 */
652 int
tcp_log_set_id(struct tcpcb * tp,char * id)653 tcp_log_set_id(struct tcpcb *tp, char *id)
654 {
655 struct tcp_log_id_bucket *tlb, *tmp_tlb;
656 struct tcp_log_id_node *tln;
657 struct inpcb *inp = tptoinpcb(tp);
658 int tree_locked, rv;
659 bool bucket_locked, same;
660
661 tlb = NULL;
662 tln = NULL;
663 tree_locked = TREE_UNLOCKED;
664 bucket_locked = false;
665
666 restart:
667 INP_WLOCK_ASSERT(inp);
668 /* See if the ID is unchanged. */
669 same = ((tp->t_lib != NULL && !strcmp(tp->t_lib->tlb_id, id)) ||
670 (tp->t_lib == NULL && *id == 0));
671 if (tp->_t_logstate && STAILQ_FIRST(&tp->t_logs) && !same) {
672 /*
673 * There are residual logs left we may
674 * be changing id's so dump what we can.
675 */
676 switch(tp->_t_logstate) {
677 case TCP_LOG_STATE_HEAD_AUTO:
678 (void)tcp_log_dump_tp_logbuf(tp, "auto-dumped from head at id switch",
679 M_NOWAIT, false);
680 break;
681 case TCP_LOG_STATE_TAIL_AUTO:
682 (void)tcp_log_dump_tp_logbuf(tp, "auto-dumped from tail at id switch",
683 M_NOWAIT, false);
684 break;
685 case TCP_LOG_STATE_CONTINUAL:
686 (void)tcp_log_dump_tp_logbuf(tp, "auto-dumped from continual at id switch",
687 M_NOWAIT, false);
688 break;
689 case TCP_LOG_VIA_BBPOINTS:
690 (void)tcp_log_dump_tp_logbuf(tp, "auto-dumped from bbpoints at id switch",
691 M_NOWAIT, false);
692 break;
693 }
694 }
695 if (same) {
696 if (tp->t_lib != NULL) {
697 tcp_log_increment_reqcnt(tp->t_lib);
698 if ((tp->t_lib->tlb_logstate > TCP_LOG_STATE_OFF) &&
699 (tp->t_log_state_set == 0)) {
700 /* Clone in any logging */
701
702 tp->_t_logstate = tp->t_lib->tlb_logstate;
703 }
704 if ((tp->t_lib->tlb_loglimit) &&
705 (tp->t_log_state_set == 0)) {
706 /* We also have a limit set */
707
708 tp->t_loglimit = tp->t_lib->tlb_loglimit;
709 }
710 }
711 rv = 0;
712 goto done;
713 }
714
715 /*
716 * If the TCPCB had a previous ID, we need to extricate it from
717 * the previous list.
718 *
719 * Drop the TCPCB lock and lock the tree and the bucket.
720 * Because this is called in the socket context, we (theoretically)
721 * don't need to worry about the INPCB completely going away
722 * while we are gone.
723 */
724 if (tp->t_lib != NULL) {
725 tlb = tp->t_lib;
726 TCPID_BUCKET_REF(tlb);
727 INP_WUNLOCK(inp);
728
729 if (tree_locked == TREE_UNLOCKED) {
730 TCPID_TREE_RLOCK();
731 tree_locked = TREE_RLOCKED;
732 }
733 TCPID_BUCKET_LOCK(tlb);
734 bucket_locked = true;
735 INP_WLOCK(inp);
736
737 /*
738 * Unreference the bucket. If our bucket went away, it is no
739 * longer locked or valid.
740 */
741 if (tcp_log_unref_bucket(tlb, &tree_locked, inp)) {
742 bucket_locked = false;
743 tlb = NULL;
744 }
745
746 /* Validate the INP. */
747 RECHECK_INP();
748
749 /*
750 * Evaluate whether the bucket changed while we were unlocked.
751 *
752 * Possible scenarios here:
753 * 1. Bucket is unchanged and the same one we started with.
754 * 2. The TCPCB no longer has a bucket and our bucket was
755 * freed.
756 * 3. The TCPCB has a new bucket, whether ours was freed.
757 * 4. The TCPCB no longer has a bucket and our bucket was
758 * not freed.
759 *
760 * In cases 2-4, we will start over. In case 1, we will
761 * proceed here to remove the bucket.
762 */
763 if (tlb == NULL || tp->t_lib != tlb) {
764 KASSERT(bucket_locked || tlb == NULL,
765 ("%s: bucket_locked (%d) and tlb (%p) are "
766 "inconsistent", __func__, bucket_locked, tlb));
767
768 if (bucket_locked) {
769 TCPID_BUCKET_UNLOCK(tlb);
770 bucket_locked = false;
771 tlb = NULL;
772 }
773 goto restart;
774 }
775
776 /*
777 * Store the (struct tcp_log_id_node) for reuse. Then, remove
778 * it from the bucket. In the process, we may end up relocking.
779 * If so, we need to validate that the INP is still valid, and
780 * the TCPCB entries match we expect.
781 *
782 * We will clear tlb and change the bucket_locked state just
783 * before calling tcp_log_remove_id_node(), since that function
784 * will unlock the bucket.
785 */
786 if (tln != NULL)
787 uma_zfree(tcp_log_id_node_zone, tln);
788 tln = tp->t_lin;
789 tlb = NULL;
790 bucket_locked = false;
791 if (tcp_log_remove_id_node(inp, tp, NULL, NULL, &tree_locked)) {
792 RECHECK_INP();
793
794 /*
795 * If the TCPCB moved to a new bucket while we had
796 * dropped the lock, restart.
797 */
798 if (tp->t_lib != NULL || tp->t_lin != NULL)
799 goto restart;
800 }
801
802 /*
803 * Yay! We successfully removed the TCPCB from its old
804 * bucket. Phew!
805 *
806 * On to bigger and better things...
807 */
808 }
809
810 /* At this point, the TCPCB should not be in any bucket. */
811 KASSERT(tp->t_lib == NULL, ("%s: tp->t_lib is not NULL", __func__));
812
813 /*
814 * If the new ID is not empty, we need to now assign this TCPCB to a
815 * new bucket.
816 */
817 if (*id) {
818 /* Get a new tln, if we don't already have one to reuse. */
819 if (tln == NULL) {
820 tln = uma_zalloc(tcp_log_id_node_zone,
821 M_NOWAIT | M_ZERO);
822 if (tln == NULL) {
823 rv = ENOBUFS;
824 goto done;
825 }
826 tln->tln_inp = inp;
827 tln->tln_tp = tp;
828 }
829
830 /*
831 * Drop the INP lock for a bit. We don't need it, and dropping
832 * it prevents lock order reversals.
833 */
834 INP_WUNLOCK(inp);
835
836 /* Make sure we have at least a read lock on the tree. */
837 tcp_log_id_validate_tree_lock(tree_locked);
838 if (tree_locked == TREE_UNLOCKED) {
839 TCPID_TREE_RLOCK();
840 tree_locked = TREE_RLOCKED;
841 }
842
843 refind:
844 /*
845 * Remember that we constructed (struct tcp_log_id_node) so
846 * we can safely cast the id to it for the purposes of finding.
847 */
848 KASSERT(tlb == NULL, ("%s:%d tlb unexpectedly non-NULL",
849 __func__, __LINE__));
850 tmp_tlb = RB_FIND(tcp_log_id_tree, &tcp_log_id_head,
851 (struct tcp_log_id_bucket *) id);
852
853 /*
854 * If we didn't find a matching bucket, we need to add a new
855 * one. This requires a write lock. But, of course, we will
856 * need to recheck some things when we re-acquire the lock.
857 */
858 if (tmp_tlb == NULL && tree_locked != TREE_WLOCKED) {
859 tree_locked = TREE_WLOCKED;
860 if (!TCPID_TREE_UPGRADE()) {
861 TCPID_TREE_RUNLOCK();
862 TCPID_TREE_WLOCK();
863
864 /*
865 * The tree may have changed while we were
866 * unlocked.
867 */
868 goto refind;
869 }
870 }
871
872 /* If we need to add a new bucket, do it now. */
873 if (tmp_tlb == NULL) {
874 /* Allocate new bucket. */
875 tlb = uma_zalloc(tcp_log_id_bucket_zone, M_NOWAIT);
876 if (tlb == NULL) {
877 rv = ENOBUFS;
878 goto done_noinp;
879 }
880 counter_u64_add(tcp_log_pcb_ids_cur, 1);
881 counter_u64_add(tcp_log_pcb_ids_tot, 1);
882
883 if ((tcp_log_auto_all == false) &&
884 tcp_log_auto_mode &&
885 tcp_log_selectauto()) {
886 /* Save off the log state */
887 tlb->tlb_logstate = tcp_log_auto_mode;
888 } else
889 tlb->tlb_logstate = TCP_LOG_STATE_OFF;
890 tlb->tlb_loglimit = 0;
891 tlb->tlb_tag[0] = '\0'; /* Default to an empty tag. */
892
893 /*
894 * Copy the ID to the bucket.
895 * NB: Don't use strlcpy() unless you are sure
896 * we've always validated NULL termination.
897 *
898 * TODO: When I'm done writing this, see if we
899 * we have correctly validated NULL termination and
900 * can use strlcpy(). :-)
901 */
902 strncpy(tlb->tlb_id, id, TCP_LOG_ID_LEN - 1);
903 tlb->tlb_id[TCP_LOG_ID_LEN - 1] = '\0';
904
905 /*
906 * Take the refcount for the first node and go ahead
907 * and lock this. Note that we zero the tlb_mtx
908 * structure, since 0xdeadc0de flips the right bits
909 * for the code to think that this mutex has already
910 * been initialized. :-(
911 */
912 SLIST_INIT(&tlb->tlb_head);
913 refcount_init(&tlb->tlb_refcnt, 1);
914 tlb->tlb_reqcnt = 1;
915 memset(&tlb->tlb_mtx, 0, sizeof(struct mtx));
916 TCPID_BUCKET_LOCK_INIT(tlb);
917 TCPID_BUCKET_LOCK(tlb);
918 bucket_locked = true;
919
920 #define FREE_NEW_TLB() do { \
921 TCPID_BUCKET_LOCK_DESTROY(tlb); \
922 uma_zfree(tcp_log_id_bucket_zone, tlb); \
923 counter_u64_add(tcp_log_pcb_ids_cur, (int64_t)-1); \
924 counter_u64_add(tcp_log_pcb_ids_tot, (int64_t)-1); \
925 bucket_locked = false; \
926 tlb = NULL; \
927 } while (0)
928 /*
929 * Relock the INP and make sure we are still
930 * unassigned.
931 */
932 INP_WLOCK(inp);
933 RECHECK_INP_CLEAN(FREE_NEW_TLB());
934 if (tp->t_lib != NULL) {
935 FREE_NEW_TLB();
936 goto restart;
937 }
938
939 /* Add the new bucket to the tree. */
940 tmp_tlb = RB_INSERT(tcp_log_id_tree, &tcp_log_id_head,
941 tlb);
942 KASSERT(tmp_tlb == NULL,
943 ("%s: Unexpected conflicting bucket (%p) while "
944 "adding new bucket (%p)", __func__, tmp_tlb, tlb));
945
946 /*
947 * If we found a conflicting bucket, free the new
948 * one we made and fall through to use the existing
949 * bucket.
950 */
951 if (tmp_tlb != NULL) {
952 FREE_NEW_TLB();
953 INP_WUNLOCK(inp);
954 }
955 #undef FREE_NEW_TLB
956 }
957
958 /* If we found an existing bucket, use it. */
959 if (tmp_tlb != NULL) {
960 tlb = tmp_tlb;
961 TCPID_BUCKET_LOCK(tlb);
962 bucket_locked = true;
963
964 /*
965 * Relock the INP and make sure we are still
966 * unassigned.
967 */
968 INP_UNLOCK_ASSERT(inp);
969 INP_WLOCK(inp);
970 RECHECK_INP();
971 if (tp->t_lib != NULL) {
972 TCPID_BUCKET_UNLOCK(tlb);
973 bucket_locked = false;
974 tlb = NULL;
975 goto restart;
976 }
977
978 /* Take a reference on the bucket. */
979 TCPID_BUCKET_REF(tlb);
980
981 /* Record the request. */
982 tcp_log_increment_reqcnt(tlb);
983 }
984
985 tcp_log_grow_tlb(tlb->tlb_id, tp);
986
987 /* Add the new node to the list. */
988 SLIST_INSERT_HEAD(&tlb->tlb_head, tln, tln_list);
989 tp->t_lib = tlb;
990 tp->t_lin = tln;
991 if (tp->t_lib->tlb_logstate > TCP_LOG_STATE_OFF) {
992 /* Clone in any logging */
993
994 tp->_t_logstate = tp->t_lib->tlb_logstate;
995 }
996 if (tp->t_lib->tlb_loglimit) {
997 /* The loglimit too */
998
999 tp->t_loglimit = tp->t_lib->tlb_loglimit;
1000 }
1001 tln = NULL;
1002 }
1003
1004 rv = 0;
1005
1006 done:
1007 /* Unlock things, as needed, and return. */
1008 INP_WUNLOCK(inp);
1009 done_noinp:
1010 INP_UNLOCK_ASSERT(inp);
1011 if (bucket_locked) {
1012 TCPID_BUCKET_LOCK_ASSERT(tlb);
1013 TCPID_BUCKET_UNLOCK(tlb);
1014 } else if (tlb != NULL)
1015 TCPID_BUCKET_UNLOCK_ASSERT(tlb);
1016 if (tree_locked == TREE_WLOCKED) {
1017 TCPID_TREE_WLOCK_ASSERT();
1018 TCPID_TREE_WUNLOCK();
1019 } else if (tree_locked == TREE_RLOCKED) {
1020 TCPID_TREE_RLOCK_ASSERT();
1021 TCPID_TREE_RUNLOCK();
1022 } else
1023 TCPID_TREE_UNLOCK_ASSERT();
1024 if (tln != NULL)
1025 uma_zfree(tcp_log_id_node_zone, tln);
1026 return (rv);
1027 }
1028
1029 /*
1030 * Get the TCP log ID for a TCPCB.
1031 * Called with INPCB locked.
1032 * 'buf' must point to a buffer that is at least TCP_LOG_ID_LEN bytes long.
1033 * Returns number of bytes copied.
1034 */
1035 size_t
tcp_log_get_id(struct tcpcb * tp,char * buf)1036 tcp_log_get_id(struct tcpcb *tp, char *buf)
1037 {
1038 size_t len;
1039
1040 INP_LOCK_ASSERT(tptoinpcb(tp));
1041 if (tp->t_lib != NULL) {
1042 len = strlcpy(buf, tp->t_lib->tlb_id, TCP_LOG_ID_LEN);
1043 KASSERT(len < TCP_LOG_ID_LEN,
1044 ("%s:%d: tp->t_lib->tlb_id too long (%zu)",
1045 __func__, __LINE__, len));
1046 } else {
1047 *buf = '\0';
1048 len = 0;
1049 }
1050 return (len);
1051 }
1052
1053 /*
1054 * Get the tag associated with the TCPCB's log ID.
1055 * Called with INPCB locked. Returns with it unlocked.
1056 * 'buf' must point to a buffer that is at least TCP_LOG_TAG_LEN bytes long.
1057 * Returns number of bytes copied.
1058 */
1059 size_t
tcp_log_get_tag(struct tcpcb * tp,char * buf)1060 tcp_log_get_tag(struct tcpcb *tp, char *buf)
1061 {
1062 struct inpcb *inp = tptoinpcb(tp);
1063 struct tcp_log_id_bucket *tlb;
1064 size_t len;
1065 int tree_locked;
1066
1067 INP_WLOCK_ASSERT(inp);
1068
1069 tree_locked = TREE_UNLOCKED;
1070 tlb = tp->t_lib;
1071
1072 if (tlb != NULL) {
1073 TCPID_BUCKET_REF(tlb);
1074 INP_WUNLOCK(inp);
1075 TCPID_BUCKET_LOCK(tlb);
1076 len = strlcpy(buf, tlb->tlb_tag, TCP_LOG_TAG_LEN);
1077 KASSERT(len < TCP_LOG_TAG_LEN,
1078 ("%s:%d: tp->t_lib->tlb_tag too long (%zu)",
1079 __func__, __LINE__, len));
1080 if (!tcp_log_unref_bucket(tlb, &tree_locked, NULL))
1081 TCPID_BUCKET_UNLOCK(tlb);
1082
1083 if (tree_locked == TREE_WLOCKED) {
1084 TCPID_TREE_WLOCK_ASSERT();
1085 TCPID_TREE_WUNLOCK();
1086 } else if (tree_locked == TREE_RLOCKED) {
1087 TCPID_TREE_RLOCK_ASSERT();
1088 TCPID_TREE_RUNLOCK();
1089 } else
1090 TCPID_TREE_UNLOCK_ASSERT();
1091 } else {
1092 INP_WUNLOCK(inp);
1093 *buf = '\0';
1094 len = 0;
1095 }
1096
1097 return (len);
1098 }
1099
1100 /*
1101 * Get number of connections with the same log ID.
1102 * Log ID is taken from given TCPCB.
1103 * Called with INPCB locked.
1104 */
1105 u_int
tcp_log_get_id_cnt(struct tcpcb * tp)1106 tcp_log_get_id_cnt(struct tcpcb *tp)
1107 {
1108
1109 INP_WLOCK_ASSERT(tptoinpcb(tp));
1110 return ((tp->t_lib == NULL) ? 0 : tp->t_lib->tlb_refcnt);
1111 }
1112
1113 #ifdef TCPLOG_DEBUG_RINGBUF
1114 /*
1115 * Functions/macros to increment/decrement reference count for a log
1116 * entry. This should catch when we do a double-free/double-remove or
1117 * a double-add.
1118 */
1119 static inline void
_tcp_log_entry_refcnt_add(struct tcp_log_mem * log_entry,const char * func,int line)1120 _tcp_log_entry_refcnt_add(struct tcp_log_mem *log_entry, const char *func,
1121 int line)
1122 {
1123 int refcnt;
1124
1125 refcnt = atomic_fetchadd_int(&log_entry->tlm_refcnt, 1);
1126 if (refcnt != 0)
1127 panic("%s:%d: log_entry(%p)->tlm_refcnt is %d (expected 0)",
1128 func, line, log_entry, refcnt);
1129 }
1130 #define tcp_log_entry_refcnt_add(l) \
1131 _tcp_log_entry_refcnt_add((l), __func__, __LINE__)
1132
1133 static inline void
_tcp_log_entry_refcnt_rem(struct tcp_log_mem * log_entry,const char * func,int line)1134 _tcp_log_entry_refcnt_rem(struct tcp_log_mem *log_entry, const char *func,
1135 int line)
1136 {
1137 int refcnt;
1138
1139 refcnt = atomic_fetchadd_int(&log_entry->tlm_refcnt, -1);
1140 if (refcnt != 1)
1141 panic("%s:%d: log_entry(%p)->tlm_refcnt is %d (expected 1)",
1142 func, line, log_entry, refcnt);
1143 }
1144 #define tcp_log_entry_refcnt_rem(l) \
1145 _tcp_log_entry_refcnt_rem((l), __func__, __LINE__)
1146
1147 #else /* !TCPLOG_DEBUG_RINGBUF */
1148
1149 #define tcp_log_entry_refcnt_add(l)
1150 #define tcp_log_entry_refcnt_rem(l)
1151
1152 #endif
1153
1154 /*
1155 * Cleanup after removing a log entry, but only decrement the count if we
1156 * are running INVARIANTS.
1157 */
1158 static inline void
tcp_log_free_log_common(struct tcp_log_mem * log_entry,int * count __unused)1159 tcp_log_free_log_common(struct tcp_log_mem *log_entry, int *count __unused)
1160 {
1161
1162 uma_zfree(tcp_log_zone, log_entry);
1163 #ifdef INVARIANTS
1164 (*count)--;
1165 KASSERT(*count >= 0,
1166 ("%s: count unexpectedly negative", __func__));
1167 #endif
1168 }
1169
1170 static void
tcp_log_free_entries(struct tcp_log_stailq * head,int * count)1171 tcp_log_free_entries(struct tcp_log_stailq *head, int *count)
1172 {
1173 struct tcp_log_mem *log_entry;
1174
1175 /* Free the entries. */
1176 while ((log_entry = STAILQ_FIRST(head)) != NULL) {
1177 STAILQ_REMOVE_HEAD(head, tlm_queue);
1178 tcp_log_entry_refcnt_rem(log_entry);
1179 tcp_log_free_log_common(log_entry, count);
1180 }
1181 }
1182
1183 /* Cleanup after removing a log entry. */
1184 static inline void
tcp_log_remove_log_cleanup(struct tcpcb * tp,struct tcp_log_mem * log_entry)1185 tcp_log_remove_log_cleanup(struct tcpcb *tp, struct tcp_log_mem *log_entry)
1186 {
1187 uma_zfree(tcp_log_zone, log_entry);
1188 tp->t_lognum--;
1189 KASSERT(tp->t_lognum >= 0,
1190 ("%s: tp->t_lognum unexpectedly negative", __func__));
1191 }
1192
1193 /* Remove a log entry from the head of a list. */
1194 static inline void
tcp_log_remove_log_head(struct tcpcb * tp,struct tcp_log_mem * log_entry)1195 tcp_log_remove_log_head(struct tcpcb *tp, struct tcp_log_mem *log_entry)
1196 {
1197
1198 KASSERT(log_entry == STAILQ_FIRST(&tp->t_logs),
1199 ("%s: attempt to remove non-HEAD log entry", __func__));
1200 STAILQ_REMOVE_HEAD(&tp->t_logs, tlm_queue);
1201 tcp_log_entry_refcnt_rem(log_entry);
1202 tcp_log_remove_log_cleanup(tp, log_entry);
1203 }
1204
1205 #ifdef TCPLOG_DEBUG_RINGBUF
1206 /*
1207 * Initialize the log entry's reference count, which we want to
1208 * survive allocations.
1209 */
1210 static int
tcp_log_zone_init(void * mem,int size,int flags __unused)1211 tcp_log_zone_init(void *mem, int size, int flags __unused)
1212 {
1213 struct tcp_log_mem *tlm;
1214
1215 KASSERT(size >= sizeof(struct tcp_log_mem),
1216 ("%s: unexpectedly short (%d) allocation", __func__, size));
1217 tlm = (struct tcp_log_mem *)mem;
1218 tlm->tlm_refcnt = 0;
1219 return (0);
1220 }
1221
1222 /*
1223 * Double check that the refcnt is zero on allocation and return.
1224 */
1225 static int
tcp_log_zone_ctor(void * mem,int size,void * args __unused,int flags __unused)1226 tcp_log_zone_ctor(void *mem, int size, void *args __unused, int flags __unused)
1227 {
1228 struct tcp_log_mem *tlm;
1229
1230 KASSERT(size >= sizeof(struct tcp_log_mem),
1231 ("%s: unexpectedly short (%d) allocation", __func__, size));
1232 tlm = (struct tcp_log_mem *)mem;
1233 if (tlm->tlm_refcnt != 0)
1234 panic("%s:%d: tlm(%p)->tlm_refcnt is %d (expected 0)",
1235 __func__, __LINE__, tlm, tlm->tlm_refcnt);
1236 return (0);
1237 }
1238
1239 static void
tcp_log_zone_dtor(void * mem,int size,void * args __unused)1240 tcp_log_zone_dtor(void *mem, int size, void *args __unused)
1241 {
1242 struct tcp_log_mem *tlm;
1243
1244 KASSERT(size >= sizeof(struct tcp_log_mem),
1245 ("%s: unexpectedly short (%d) allocation", __func__, size));
1246 tlm = (struct tcp_log_mem *)mem;
1247 if (tlm->tlm_refcnt != 0)
1248 panic("%s:%d: tlm(%p)->tlm_refcnt is %d (expected 0)",
1249 __func__, __LINE__, tlm, tlm->tlm_refcnt);
1250 }
1251 #endif /* TCPLOG_DEBUG_RINGBUF */
1252
1253 /* Do global initialization. */
1254 void
tcp_log_init(void)1255 tcp_log_init(void)
1256 {
1257
1258 tcp_log_zone = uma_zcreate("tcp_log", sizeof(struct tcp_log_mem),
1259 #ifdef TCPLOG_DEBUG_RINGBUF
1260 tcp_log_zone_ctor, tcp_log_zone_dtor, tcp_log_zone_init,
1261 #else
1262 NULL, NULL, NULL,
1263 #endif
1264 NULL, UMA_ALIGN_PTR, 0);
1265 (void)uma_zone_set_max(tcp_log_zone, TCP_LOG_BUF_DEFAULT_GLOBAL_LIMIT);
1266 tcp_log_id_bucket_zone = uma_zcreate("tcp_log_id_bucket",
1267 sizeof(struct tcp_log_id_bucket), NULL, NULL, NULL, NULL,
1268 UMA_ALIGN_PTR, 0);
1269 tcp_log_id_node_zone = uma_zcreate("tcp_log_id_node",
1270 sizeof(struct tcp_log_id_node), NULL, NULL, NULL, NULL,
1271 UMA_ALIGN_PTR, 0);
1272 #ifdef TCPLOG_DEBUG_COUNTERS
1273 tcp_log_queued = counter_u64_alloc(M_WAITOK);
1274 tcp_log_que_fail1 = counter_u64_alloc(M_WAITOK);
1275 tcp_log_que_fail2 = counter_u64_alloc(M_WAITOK);
1276 tcp_log_que_fail3 = counter_u64_alloc(M_WAITOK);
1277 tcp_log_que_fail4 = counter_u64_alloc(M_WAITOK);
1278 tcp_log_que_fail5 = counter_u64_alloc(M_WAITOK);
1279 tcp_log_que_copyout = counter_u64_alloc(M_WAITOK);
1280 tcp_log_que_read = counter_u64_alloc(M_WAITOK);
1281 tcp_log_que_freed = counter_u64_alloc(M_WAITOK);
1282 #endif
1283 tcp_log_pcb_ids_cur = counter_u64_alloc(M_WAITOK);
1284 tcp_log_pcb_ids_tot = counter_u64_alloc(M_WAITOK);
1285
1286 rw_init_flags(&tcp_id_tree_lock, "TCP ID tree", RW_NEW);
1287 mtx_init(&tcp_log_expireq_mtx, "TCP log expireq", NULL, MTX_DEF);
1288 callout_init(&tcp_log_expireq_callout, 1);
1289 }
1290
1291 /* Do per-TCPCB initialization. */
1292 void
tcp_log_tcpcbinit(struct tcpcb * tp)1293 tcp_log_tcpcbinit(struct tcpcb *tp)
1294 {
1295
1296 /* A new TCPCB should start out zero-initialized. */
1297 STAILQ_INIT(&tp->t_logs);
1298
1299 /*
1300 * If we are doing auto-capturing, figure out whether we will capture
1301 * this session.
1302 */
1303 tp->t_loglimit = tcp_log_session_limit;
1304 if ((tcp_log_auto_all == true) &&
1305 tcp_log_auto_mode &&
1306 tcp_log_selectauto()) {
1307 tp->_t_logstate = tcp_log_auto_mode;
1308 tp->t_flags2 |= TF2_LOG_AUTO;
1309 }
1310 }
1311
1312 /* Remove entries */
1313 static void
tcp_log_expire(void * unused __unused)1314 tcp_log_expire(void *unused __unused)
1315 {
1316 struct tcp_log_id_bucket *tlb;
1317 struct tcp_log_id_node *tln;
1318 sbintime_t expiry_limit;
1319 int tree_locked;
1320
1321 TCPLOG_EXPIREQ_LOCK();
1322 if (callout_pending(&tcp_log_expireq_callout)) {
1323 /* Callout was reset. */
1324 TCPLOG_EXPIREQ_UNLOCK();
1325 return;
1326 }
1327
1328 /*
1329 * Process entries until we reach one that expires too far in the
1330 * future. Look one second in the future.
1331 */
1332 expiry_limit = getsbinuptime() + SBT_1S;
1333 tree_locked = TREE_UNLOCKED;
1334
1335 while ((tln = STAILQ_FIRST(&tcp_log_expireq_head)) != NULL &&
1336 tln->tln_expiretime <= expiry_limit) {
1337 if (!callout_active(&tcp_log_expireq_callout)) {
1338 /*
1339 * Callout was stopped. I guess we should
1340 * just quit at this point.
1341 */
1342 TCPLOG_EXPIREQ_UNLOCK();
1343 return;
1344 }
1345
1346 /*
1347 * Remove the node from the head of the list and unlock
1348 * the list. Change the expiry time to SBT_MAX as a signal
1349 * to other threads that we now own this.
1350 */
1351 STAILQ_REMOVE_HEAD(&tcp_log_expireq_head, tln_expireq);
1352 tln->tln_expiretime = SBT_MAX;
1353 TCPLOG_EXPIREQ_UNLOCK();
1354
1355 /*
1356 * Remove the node from the bucket.
1357 */
1358 tlb = tln->tln_bucket;
1359 TCPID_BUCKET_LOCK(tlb);
1360 if (tcp_log_remove_id_node(NULL, NULL, tlb, tln, &tree_locked)) {
1361 tcp_log_id_validate_tree_lock(tree_locked);
1362 if (tree_locked == TREE_WLOCKED)
1363 TCPID_TREE_WUNLOCK();
1364 else
1365 TCPID_TREE_RUNLOCK();
1366 tree_locked = TREE_UNLOCKED;
1367 }
1368
1369 /* Drop the INP reference. */
1370 INP_WLOCK(tln->tln_inp);
1371 if (!in_pcbrele_wlocked(tln->tln_inp))
1372 INP_WUNLOCK(tln->tln_inp);
1373
1374 /* Free the log records. */
1375 tcp_log_free_entries(&tln->tln_entries, &tln->tln_count);
1376
1377 /* Free the node. */
1378 uma_zfree(tcp_log_id_node_zone, tln);
1379
1380 /* Relock the expiry queue. */
1381 TCPLOG_EXPIREQ_LOCK();
1382 }
1383
1384 /*
1385 * We've expired all the entries we can. Do we need to reschedule
1386 * ourselves?
1387 */
1388 callout_deactivate(&tcp_log_expireq_callout);
1389 if (tln != NULL) {
1390 /*
1391 * Get max(now + TCP_LOG_EXPIRE_INTVL, tln->tln_expiretime) and
1392 * set the next callout to that. (This helps ensure we generally
1393 * run the callout no more often than desired.)
1394 */
1395 expiry_limit = getsbinuptime() + TCP_LOG_EXPIRE_INTVL;
1396 if (expiry_limit < tln->tln_expiretime)
1397 expiry_limit = tln->tln_expiretime;
1398 callout_reset_sbt(&tcp_log_expireq_callout, expiry_limit,
1399 SBT_1S, tcp_log_expire, NULL, C_ABSOLUTE);
1400 }
1401
1402 /* We're done. */
1403 TCPLOG_EXPIREQ_UNLOCK();
1404 return;
1405 }
1406
1407 /*
1408 * Move log data from the TCPCB to a new node. This will reset the TCPCB log
1409 * entries and log count; however, it will not touch other things from the
1410 * TCPCB (e.g. t_lin, t_lib).
1411 *
1412 * NOTE: Must hold a lock on the INP.
1413 */
1414 static void
tcp_log_move_tp_to_node(struct tcpcb * tp,struct tcp_log_id_node * tln)1415 tcp_log_move_tp_to_node(struct tcpcb *tp, struct tcp_log_id_node *tln)
1416 {
1417 struct inpcb *inp = tptoinpcb(tp);
1418
1419 INP_WLOCK_ASSERT(inp);
1420
1421 tln->tln_ie = inp->inp_inc.inc_ie;
1422 if (inp->inp_inc.inc_flags & INC_ISIPV6)
1423 tln->tln_af = AF_INET6;
1424 else
1425 tln->tln_af = AF_INET;
1426 tln->tln_entries = tp->t_logs;
1427 tln->tln_count = tp->t_lognum;
1428 tln->tln_bucket = tp->t_lib;
1429
1430 /* Clear information from the PCB. */
1431 STAILQ_INIT(&tp->t_logs);
1432 tp->t_lognum = 0;
1433 }
1434
1435 /* Do per-TCPCB cleanup */
1436 void
tcp_log_tcpcbfini(struct tcpcb * tp)1437 tcp_log_tcpcbfini(struct tcpcb *tp)
1438 {
1439 struct tcp_log_id_node *tln, *tln_first;
1440 struct tcp_log_mem *log_entry;
1441 sbintime_t callouttime;
1442
1443
1444 INP_WLOCK_ASSERT(tptoinpcb(tp));
1445 if (tp->_t_logstate) {
1446 union tcp_log_stackspecific log;
1447 struct timeval tv;
1448 #ifdef TCP_ACCOUNTING
1449 struct tcp_log_buffer *lgb;
1450 int i;
1451
1452 memset(&log, 0, sizeof(log));
1453 if (tp->t_flags2 & TF2_TCP_ACCOUNTING) {
1454 for (i = 0; i < TCP_NUM_CNT_COUNTERS; i++) {
1455 log.u_raw.u64_flex[i] = tp->tcp_cnt_counters[i];
1456 }
1457 lgb = tcp_log_event(tp, NULL,
1458 NULL,
1459 NULL,
1460 TCP_LOG_ACCOUNTING, 0,
1461 0, &log, false, NULL, NULL, 0, &tv);
1462 if (lgb != NULL) {
1463 lgb->tlb_flex1 = TCP_NUM_CNT_COUNTERS;
1464 lgb->tlb_flex2 = 1;
1465 } else
1466 goto skip_out;
1467 for (i = 0; i<TCP_NUM_CNT_COUNTERS; i++) {
1468 log.u_raw.u64_flex[i] = tp->tcp_proc_time[i];
1469 }
1470 lgb = tcp_log_event(tp, NULL,
1471 NULL,
1472 NULL,
1473 TCP_LOG_ACCOUNTING, 0,
1474 0, &log, false, NULL, NULL, 0, &tv);
1475 if (lgb != NULL) {
1476 lgb->tlb_flex1 = TCP_NUM_CNT_COUNTERS;
1477 lgb->tlb_flex2 = 2;
1478 }
1479 }
1480 skip_out:
1481 #endif
1482 log.u_bbr.timeStamp = tcp_get_usecs(&tv);
1483 log.u_bbr.cur_del_rate = tp->t_end_info;
1484 (void)tcp_log_event(tp, NULL,
1485 NULL,
1486 NULL,
1487 TCP_LOG_CONNEND, 0,
1488 0, &log, false, NULL, NULL, 0, &tv);
1489 }
1490 /*
1491 * If we were gathering packets to be automatically dumped, try to do
1492 * it now. If this succeeds, the log information in the TCPCB will be
1493 * cleared. Otherwise, we'll handle the log information as we do
1494 * for other states.
1495 */
1496 switch(tp->_t_logstate) {
1497 case TCP_LOG_STATE_HEAD_AUTO:
1498 (void)tcp_log_dump_tp_logbuf(tp, "auto-dumped from head",
1499 M_NOWAIT, false);
1500 break;
1501 case TCP_LOG_STATE_TAIL_AUTO:
1502 (void)tcp_log_dump_tp_logbuf(tp, "auto-dumped from tail",
1503 M_NOWAIT, false);
1504 break;
1505 case TCP_LOG_VIA_BBPOINTS:
1506 (void)tcp_log_dump_tp_logbuf(tp, "auto-dumped from bbpoints",
1507 M_NOWAIT, false);
1508 break;
1509 case TCP_LOG_STATE_CONTINUAL:
1510 (void)tcp_log_dump_tp_logbuf(tp, "auto-dumped from continual",
1511 M_NOWAIT, false);
1512 break;
1513 }
1514
1515 /*
1516 * There are two ways we could keep logs: per-socket or per-ID. If
1517 * we are tracking logs with an ID, then the logs survive the
1518 * destruction of the TCPCB.
1519 *
1520 * If the TCPCB is associated with an ID node, move the logs from the
1521 * TCPCB to the ID node. In theory, this is safe, for reasons which I
1522 * will now explain for my own benefit when I next need to figure out
1523 * this code. :-)
1524 *
1525 * We own the INP lock. Therefore, no one else can change the contents
1526 * of this node (Rule C). Further, no one can remove this node from
1527 * the bucket while we hold the lock (Rule D). Basically, no one can
1528 * mess with this node. That leaves two states in which we could be:
1529 *
1530 * 1. Another thread is currently waiting to acquire the INP lock, with
1531 * plans to do something with this node. When we drop the INP lock,
1532 * they will have a chance to do that. They will recheck the
1533 * tln_closed field (see note to Rule C) and then acquire the
1534 * bucket lock before proceeding further.
1535 *
1536 * 2. Another thread will try to acquire a lock at some point in the
1537 * future. If they try to acquire a lock before we set the
1538 * tln_closed field, they will follow state #1. If they try to
1539 * acquire a lock after we set the tln_closed field, they will be
1540 * able to make changes to the node, at will, following Rule C.
1541 *
1542 * Therefore, we currently own this node and can make any changes
1543 * we want. But, as soon as we set the tln_closed field to true, we
1544 * have effectively dropped our lock on the node. (For this reason, we
1545 * also need to make sure our writes are ordered correctly. An atomic
1546 * operation with "release" semantics should be sufficient.)
1547 */
1548
1549 if (tp->t_lin != NULL) {
1550 struct inpcb *inp = tptoinpcb(tp);
1551
1552 /* Copy the relevant information to the log entry. */
1553 tln = tp->t_lin;
1554 KASSERT(tln->tln_inp == inp,
1555 ("%s: Mismatched inp (tln->tln_inp=%p, tp inpcb=%p)",
1556 __func__, tln->tln_inp, inp));
1557 tcp_log_move_tp_to_node(tp, tln);
1558
1559 /* Clear information from the PCB. */
1560 tp->t_lin = NULL;
1561 tp->t_lib = NULL;
1562
1563 /*
1564 * Take a reference on the INP. This ensures that the INP
1565 * remains valid while the node is on the expiry queue. This
1566 * ensures the INP is valid for other threads that may be
1567 * racing to lock this node when we move it to the expire
1568 * queue.
1569 */
1570 in_pcbref(inp);
1571
1572 /*
1573 * Store the entry on the expiry list. The exact behavior
1574 * depends on whether we have entries to keep. If so, we
1575 * put the entry at the tail of the list and expire in
1576 * TCP_LOG_EXPIRE_TIME. Otherwise, we expire "now" and put
1577 * the entry at the head of the list. (Handling the cleanup
1578 * via the expiry timer lets us avoid locking messy-ness here.)
1579 */
1580 tln->tln_expiretime = getsbinuptime();
1581 TCPLOG_EXPIREQ_LOCK();
1582 if (tln->tln_count) {
1583 tln->tln_expiretime += TCP_LOG_EXPIRE_TIME;
1584 if (STAILQ_EMPTY(&tcp_log_expireq_head) &&
1585 !callout_active(&tcp_log_expireq_callout)) {
1586 /*
1587 * We are adding the first entry and a callout
1588 * is not currently scheduled; therefore, we
1589 * need to schedule one.
1590 */
1591 callout_reset_sbt(&tcp_log_expireq_callout,
1592 tln->tln_expiretime, SBT_1S, tcp_log_expire,
1593 NULL, C_ABSOLUTE);
1594 }
1595 STAILQ_INSERT_TAIL(&tcp_log_expireq_head, tln,
1596 tln_expireq);
1597 } else {
1598 callouttime = tln->tln_expiretime +
1599 TCP_LOG_EXPIRE_INTVL;
1600 tln_first = STAILQ_FIRST(&tcp_log_expireq_head);
1601
1602 if ((tln_first == NULL ||
1603 callouttime < tln_first->tln_expiretime) &&
1604 (callout_pending(&tcp_log_expireq_callout) ||
1605 !callout_active(&tcp_log_expireq_callout))) {
1606 /*
1607 * The list is empty, or we want to run the
1608 * expire code before the first entry's timer
1609 * fires. Also, we are in a case where a callout
1610 * is not actively running. We want to reset
1611 * the callout to occur sooner.
1612 */
1613 callout_reset_sbt(&tcp_log_expireq_callout,
1614 callouttime, SBT_1S, tcp_log_expire, NULL,
1615 C_ABSOLUTE);
1616 }
1617
1618 /*
1619 * Insert to the head, or just after the head, as
1620 * appropriate. (This might result in small
1621 * mis-orderings as a bunch of "expire now" entries
1622 * gather at the start of the list, but that should
1623 * not produce big problems, since the expire timer
1624 * will walk through all of them.)
1625 */
1626 if (tln_first == NULL ||
1627 tln->tln_expiretime < tln_first->tln_expiretime)
1628 STAILQ_INSERT_HEAD(&tcp_log_expireq_head, tln,
1629 tln_expireq);
1630 else
1631 STAILQ_INSERT_AFTER(&tcp_log_expireq_head,
1632 tln_first, tln, tln_expireq);
1633 }
1634 TCPLOG_EXPIREQ_UNLOCK();
1635
1636 /*
1637 * We are done messing with the tln. After this point, we
1638 * can't touch it. (Note that the "release" semantics should
1639 * be included with the TCPLOG_EXPIREQ_UNLOCK() call above.
1640 * Therefore, they should be unnecessary here. However, it
1641 * seems like a good idea to include them anyway, since we
1642 * really are releasing a lock here.)
1643 */
1644 atomic_store_rel_int(&tln->tln_closed, 1);
1645 } else {
1646 /* Remove log entries. */
1647 while ((log_entry = STAILQ_FIRST(&tp->t_logs)) != NULL)
1648 tcp_log_remove_log_head(tp, log_entry);
1649 KASSERT(tp->t_lognum == 0,
1650 ("%s: After freeing entries, tp->t_lognum=%d (expected 0)",
1651 __func__, tp->t_lognum));
1652 }
1653
1654 /*
1655 * Change the log state to off (just in case anything tries to sneak
1656 * in a last-minute log).
1657 */
1658 tp->_t_logstate = TCP_LOG_STATE_OFF;
1659 }
1660
1661 static void
tcp_log_purge_tp_logbuf(struct tcpcb * tp)1662 tcp_log_purge_tp_logbuf(struct tcpcb *tp)
1663 {
1664 struct tcp_log_mem *log_entry;
1665
1666 INP_WLOCK_ASSERT(tptoinpcb(tp));
1667 if (tp->t_lognum == 0)
1668 return;
1669
1670 while ((log_entry = STAILQ_FIRST(&tp->t_logs)) != NULL)
1671 tcp_log_remove_log_head(tp, log_entry);
1672 KASSERT(tp->t_lognum == 0,
1673 ("%s: After freeing entries, tp->t_lognum=%d (expected 0)",
1674 __func__, tp->t_lognum));
1675 tp->_t_logstate = TCP_LOG_STATE_OFF;
1676 }
1677
1678 /*
1679 * This logs an event for a TCP socket. Normally, this is called via
1680 * TCP_LOG_EVENT or TCP_LOG_EVENT_VERBOSE. See the documentation for
1681 * TCP_LOG_EVENT().
1682 */
1683
1684 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)1685 tcp_log_event(struct tcpcb *tp, struct tcphdr *th, struct sockbuf *rxbuf,
1686 struct sockbuf *txbuf, uint8_t eventid, int errornum, uint32_t len,
1687 union tcp_log_stackspecific *stackinfo, int th_hostorder,
1688 const char *output_caller, const char *func, int line, const struct timeval *itv)
1689 {
1690 struct tcp_log_mem *log_entry;
1691 struct tcp_log_buffer *log_buf;
1692 int attempt_count = 0;
1693 struct tcp_log_verbose *log_verbose;
1694 uint32_t logsn;
1695
1696 KASSERT((func == NULL && line == 0) || (func != NULL && line > 0),
1697 ("%s called with inconsistent func (%p) and line (%d) arguments",
1698 __func__, func, line));
1699
1700 INP_WLOCK_ASSERT(tptoinpcb(tp));
1701 if (tcp_disable_all_bb_logs) {
1702 /*
1703 * The global shutdown logging
1704 * switch has been thrown. Call
1705 * the purge function that frees
1706 * purges out the logs and
1707 * turns off logging.
1708 */
1709 tcp_log_purge_tp_logbuf(tp);
1710 return (NULL);
1711 }
1712 KASSERT(tp->_t_logstate == TCP_LOG_STATE_HEAD ||
1713 tp->_t_logstate == TCP_LOG_STATE_TAIL ||
1714 tp->_t_logstate == TCP_LOG_STATE_CONTINUAL ||
1715 tp->_t_logstate == TCP_LOG_STATE_HEAD_AUTO ||
1716 tp->_t_logstate == TCP_LOG_VIA_BBPOINTS ||
1717 tp->_t_logstate == TCP_LOG_STATE_TAIL_AUTO,
1718 ("%s called with unexpected tp->_t_logstate (%d)", __func__,
1719 tp->_t_logstate));
1720
1721 /*
1722 * Get the serial number. We do this early so it will
1723 * increment even if we end up skipping the log entry for some
1724 * reason.
1725 */
1726 logsn = tp->t_logsn++;
1727
1728 /*
1729 * Can we get a new log entry? If so, increment the lognum counter
1730 * here.
1731 */
1732 retry:
1733 if (tp->t_lognum < tp->t_loglimit) {
1734 if ((log_entry = uma_zalloc(tcp_log_zone, M_NOWAIT)) != NULL)
1735 tp->t_lognum++;
1736 } else
1737 log_entry = NULL;
1738
1739 /* Do we need to try to reuse? */
1740 if (log_entry == NULL) {
1741 /*
1742 * Sacrifice auto-logged sessions without a log ID if
1743 * tcp_log_auto_all is false. (If they don't have a log
1744 * ID by now, it is probable that either they won't get one
1745 * or we are resource-constrained.)
1746 */
1747 if (tp->t_lib == NULL && (tp->t_flags2 & TF2_LOG_AUTO) &&
1748 !tcp_log_auto_all) {
1749 if (tcp_log_state_change(tp, TCP_LOG_STATE_CLEAR)) {
1750 #ifdef INVARIANTS
1751 panic("%s:%d: tcp_log_state_change() failed "
1752 "to set tp %p to TCP_LOG_STATE_CLEAR",
1753 __func__, __LINE__, tp);
1754 #endif
1755 tp->_t_logstate = TCP_LOG_STATE_OFF;
1756 }
1757 return (NULL);
1758 }
1759 /*
1760 * If we are in TCP_LOG_STATE_HEAD_AUTO state, try to dump
1761 * the buffers. If successful, deactivate tracing. Otherwise,
1762 * leave it active so we will retry.
1763 */
1764 if (tp->_t_logstate == TCP_LOG_STATE_HEAD_AUTO &&
1765 !tcp_log_dump_tp_logbuf(tp, "auto-dumped from head",
1766 M_NOWAIT, false)) {
1767 tp->_t_logstate = TCP_LOG_STATE_OFF;
1768 return(NULL);
1769 } else if ((tp->_t_logstate == TCP_LOG_STATE_CONTINUAL) &&
1770 !tcp_log_dump_tp_logbuf(tp, "auto-dumped from continual",
1771 M_NOWAIT, false)) {
1772 if (attempt_count == 0) {
1773 attempt_count++;
1774 goto retry;
1775 }
1776 #ifdef TCPLOG_DEBUG_COUNTERS
1777 counter_u64_add(tcp_log_que_fail4, 1);
1778 #endif
1779 return(NULL);
1780
1781 } else if ((tp->_t_logstate == TCP_LOG_VIA_BBPOINTS) &&
1782 !tcp_log_dump_tp_logbuf(tp, "auto-dumped from bbpoints",
1783 M_NOWAIT, false)) {
1784 if (attempt_count == 0) {
1785 attempt_count++;
1786 goto retry;
1787 }
1788 #ifdef TCPLOG_DEBUG_COUNTERS
1789 counter_u64_add(tcp_log_que_fail4, 1);
1790 #endif
1791 return(NULL);
1792 } else if (tp->_t_logstate == TCP_LOG_STATE_HEAD_AUTO)
1793 return(NULL);
1794
1795 /* If in HEAD state, just deactivate the tracing and return. */
1796 if (tp->_t_logstate == TCP_LOG_STATE_HEAD) {
1797 tp->_t_logstate = TCP_LOG_STATE_OFF;
1798 return(NULL);
1799 }
1800 /*
1801 * Get a buffer to reuse. If that fails, just give up.
1802 * (We can't log anything without a buffer in which to
1803 * put it.)
1804 *
1805 * Note that we don't change the t_lognum counter
1806 * here. Because we are re-using the buffer, the total
1807 * number won't change.
1808 */
1809 if ((log_entry = STAILQ_FIRST(&tp->t_logs)) == NULL)
1810 return(NULL);
1811 STAILQ_REMOVE_HEAD(&tp->t_logs, tlm_queue);
1812 tcp_log_entry_refcnt_rem(log_entry);
1813 }
1814
1815 KASSERT(log_entry != NULL,
1816 ("%s: log_entry unexpectedly NULL", __func__));
1817
1818 /* Extract the log buffer and verbose buffer pointers. */
1819 log_buf = &log_entry->tlm_buf;
1820 log_verbose = &log_entry->tlm_v;
1821
1822 /* Basic entries. */
1823 if (itv == NULL)
1824 microuptime(&log_buf->tlb_tv);
1825 else
1826 memcpy(&log_buf->tlb_tv, itv, sizeof(struct timeval));
1827 log_buf->tlb_ticks = ticks;
1828 log_buf->tlb_sn = logsn;
1829 log_buf->tlb_stackid = tp->t_fb->tfb_id;
1830 log_buf->tlb_eventid = eventid;
1831 log_buf->tlb_eventflags = 0;
1832 log_buf->tlb_errno = errornum;
1833
1834 /* Socket buffers */
1835 if (rxbuf != NULL) {
1836 log_buf->tlb_eventflags |= TLB_FLAG_RXBUF;
1837 log_buf->tlb_rxbuf.tls_sb_acc = rxbuf->sb_acc;
1838 log_buf->tlb_rxbuf.tls_sb_ccc = rxbuf->sb_ccc;
1839 log_buf->tlb_rxbuf.tls_sb_spare = 0;
1840 } else {
1841 log_buf->tlb_rxbuf.tls_sb_acc = 0;
1842 log_buf->tlb_rxbuf.tls_sb_ccc = 0;
1843 }
1844 if (txbuf != NULL) {
1845 log_buf->tlb_eventflags |= TLB_FLAG_TXBUF;
1846 log_buf->tlb_txbuf.tls_sb_acc = txbuf->sb_acc;
1847 log_buf->tlb_txbuf.tls_sb_ccc = txbuf->sb_ccc;
1848 log_buf->tlb_txbuf.tls_sb_spare = 0;
1849 } else {
1850 log_buf->tlb_txbuf.tls_sb_acc = 0;
1851 log_buf->tlb_txbuf.tls_sb_ccc = 0;
1852 }
1853 /* Copy values from tp to the log entry. */
1854 log_buf->tlb_state = tp->t_state;
1855 log_buf->tlb_starttime = tp->t_starttime;
1856 log_buf->tlb_iss = tp->iss;
1857 log_buf->tlb_flags = tp->t_flags;
1858 log_buf->tlb_snd_una = tp->snd_una;
1859 log_buf->tlb_snd_max = tp->snd_max;
1860 log_buf->tlb_snd_cwnd = tp->snd_cwnd;
1861 log_buf->tlb_snd_nxt = tp->snd_nxt;
1862 log_buf->tlb_snd_recover = tp->snd_recover;
1863 log_buf->tlb_snd_wnd = tp->snd_wnd;
1864 log_buf->tlb_snd_ssthresh = tp->snd_ssthresh;
1865 log_buf->tlb_srtt = tp->t_srtt;
1866 log_buf->tlb_rttvar = tp->t_rttvar;
1867 log_buf->tlb_rcv_up = tp->rcv_up;
1868 log_buf->tlb_rcv_adv = tp->rcv_adv;
1869 log_buf->tlb_flags2 = tp->t_flags2;
1870 log_buf->tlb_rcv_nxt = tp->rcv_nxt;
1871 log_buf->tlb_rcv_wnd = tp->rcv_wnd;
1872 log_buf->tlb_dupacks = tp->t_dupacks;
1873 log_buf->tlb_segqlen = tp->t_segqlen;
1874 log_buf->tlb_snd_numholes = tp->snd_numholes;
1875 log_buf->tlb_flex1 = 0;
1876 log_buf->tlb_flex2 = 0;
1877 log_buf->tlb_fbyte_in = tp->t_fbyte_in;
1878 log_buf->tlb_fbyte_out = tp->t_fbyte_out;
1879 log_buf->tlb_snd_scale = tp->snd_scale;
1880 log_buf->tlb_rcv_scale = tp->rcv_scale;
1881 log_buf->_pad[0] = 0;
1882 log_buf->_pad[1] = 0;
1883 log_buf->_pad[2] = 0;
1884 /* Copy stack-specific info. */
1885 if (stackinfo != NULL) {
1886 memcpy(&log_buf->tlb_stackinfo, stackinfo,
1887 sizeof(log_buf->tlb_stackinfo));
1888 log_buf->tlb_eventflags |= TLB_FLAG_STACKINFO;
1889 }
1890
1891 /* The packet */
1892 log_buf->tlb_len = len;
1893 if (th) {
1894 int optlen;
1895
1896 log_buf->tlb_eventflags |= TLB_FLAG_HDR;
1897 log_buf->tlb_th = *th;
1898 if (th_hostorder)
1899 tcp_fields_to_net(&log_buf->tlb_th);
1900 optlen = (th->th_off << 2) - sizeof (struct tcphdr);
1901 if (optlen > 0)
1902 memcpy(log_buf->tlb_opts, th + 1, optlen);
1903 } else {
1904 memset(&log_buf->tlb_th, 0, sizeof(*th));
1905 }
1906
1907 /* Verbose information */
1908 if (func != NULL) {
1909 log_buf->tlb_eventflags |= TLB_FLAG_VERBOSE;
1910 if (output_caller != NULL)
1911 strlcpy(log_verbose->tlv_snd_frm, output_caller,
1912 TCP_FUNC_LEN);
1913 else
1914 *log_verbose->tlv_snd_frm = 0;
1915 strlcpy(log_verbose->tlv_trace_func, func, TCP_FUNC_LEN);
1916 log_verbose->tlv_trace_line = line;
1917 }
1918
1919 /* Insert the new log at the tail. */
1920 STAILQ_INSERT_TAIL(&tp->t_logs, log_entry, tlm_queue);
1921 tcp_log_entry_refcnt_add(log_entry);
1922 return (log_buf);
1923 }
1924
1925 /*
1926 * Change the logging state for a TCPCB. Returns 0 on success or an
1927 * error code on failure.
1928 */
1929 int
tcp_log_state_change(struct tcpcb * tp,int state)1930 tcp_log_state_change(struct tcpcb *tp, int state)
1931 {
1932 struct tcp_log_mem *log_entry;
1933 int rv;
1934
1935 INP_WLOCK_ASSERT(tptoinpcb(tp));
1936 rv = 0;
1937 switch(state) {
1938 case TCP_LOG_STATE_CLEAR:
1939 while ((log_entry = STAILQ_FIRST(&tp->t_logs)) != NULL)
1940 tcp_log_remove_log_head(tp, log_entry);
1941 /* FALLTHROUGH */
1942
1943 case TCP_LOG_STATE_OFF:
1944 tp->_t_logstate = TCP_LOG_STATE_OFF;
1945 break;
1946
1947 case TCP_LOG_STATE_TAIL:
1948 case TCP_LOG_STATE_HEAD:
1949 case TCP_LOG_STATE_CONTINUAL:
1950 case TCP_LOG_VIA_BBPOINTS:
1951 case TCP_LOG_STATE_HEAD_AUTO:
1952 case TCP_LOG_STATE_TAIL_AUTO:
1953 /*
1954 * When the RATIO_OFF state is set for the bucket, the log ID
1955 * this tp is associated with has been probabilistically opted
1956 * out of logging per tcp_log_apply_ratio().
1957 */
1958 if (tp->t_lib == NULL ||
1959 tp->t_lib->tlb_logstate != TCP_LOG_STATE_RATIO_OFF) {
1960 tp->_t_logstate = state;
1961 } else {
1962 rv = ECANCELED;
1963 tp->_t_logstate = TCP_LOG_STATE_OFF;
1964 }
1965 break;
1966
1967 default:
1968 return (EINVAL);
1969 }
1970 if (tcp_disable_all_bb_logs) {
1971 /* We are prohibited from doing any logs */
1972 tp->_t_logstate = TCP_LOG_STATE_OFF;
1973 rv = EBUSY;
1974 }
1975 tp->t_flags2 &= ~(TF2_LOG_AUTO);
1976
1977 return (rv);
1978 }
1979
1980 /* If tcp_drain() is called, flush half the log entries. */
1981 void
tcp_log_drain(struct tcpcb * tp)1982 tcp_log_drain(struct tcpcb *tp)
1983 {
1984 struct tcp_log_mem *log_entry, *next;
1985 int target, skip;
1986
1987 INP_WLOCK_ASSERT(tptoinpcb(tp));
1988 if ((target = tp->t_lognum / 2) == 0)
1989 return;
1990
1991 /*
1992 * XXXRRS: At this I don't think this is wise that
1993 * we do this. All that a drain call means is that
1994 * we are hitting one of the system mbuf limits. BB
1995 * logging, or freeing of them, will not create any
1996 * more mbufs and really has nothing to do with
1997 * the system running out of mbufs. For now I
1998 * am changing this to free any "AUTO" by dumping
1999 * them out. But this should either be changed
2000 * so that it gets called when we hit the BB limit
2001 * or it should just not get called (one of the two)
2002 * since I don't think the mbuf <-> BB log cleanup
2003 * is the right thing to do here.
2004 */
2005 /*
2006 * If we are logging the "head" packets, we want to discard
2007 * from the tail of the queue. Otherwise, we want to discard
2008 * from the head.
2009 */
2010 if (tp->_t_logstate == TCP_LOG_STATE_HEAD) {
2011 skip = tp->t_lognum - target;
2012 STAILQ_FOREACH(log_entry, &tp->t_logs, tlm_queue)
2013 if (!--skip)
2014 break;
2015 KASSERT(log_entry != NULL,
2016 ("%s: skipped through all entries!", __func__));
2017 if (log_entry == NULL)
2018 return;
2019 while ((next = STAILQ_NEXT(log_entry, tlm_queue)) != NULL) {
2020 STAILQ_REMOVE_AFTER(&tp->t_logs, log_entry, tlm_queue);
2021 tcp_log_entry_refcnt_rem(next);
2022 tcp_log_remove_log_cleanup(tp, next);
2023 #ifdef INVARIANTS
2024 target--;
2025 #endif
2026 }
2027 KASSERT(target == 0,
2028 ("%s: After removing from tail, target was %d", __func__,
2029 target));
2030 } else if (tp->_t_logstate == TCP_LOG_STATE_HEAD_AUTO) {
2031 (void)tcp_log_dump_tp_logbuf(tp, "auto-dumped from head at drain",
2032 M_NOWAIT, false);
2033 } else if (tp->_t_logstate == TCP_LOG_STATE_TAIL_AUTO) {
2034 (void)tcp_log_dump_tp_logbuf(tp, "auto-dumped from tail at drain",
2035 M_NOWAIT, false);
2036 } else if (tp->_t_logstate == TCP_LOG_VIA_BBPOINTS) {
2037 (void)tcp_log_dump_tp_logbuf(tp, "auto-dumped from bbpoints",
2038 M_NOWAIT, false);
2039 } else if (tp->_t_logstate == TCP_LOG_STATE_CONTINUAL) {
2040 (void)tcp_log_dump_tp_logbuf(tp, "auto-dumped from continual",
2041 M_NOWAIT, false);
2042 } else {
2043 while ((log_entry = STAILQ_FIRST(&tp->t_logs)) != NULL &&
2044 target--)
2045 tcp_log_remove_log_head(tp, log_entry);
2046 KASSERT(target <= 0,
2047 ("%s: After removing from head, target was %d", __func__,
2048 target));
2049 KASSERT(tp->t_lognum > 0,
2050 ("%s: After removing from head, tp->t_lognum was %d",
2051 __func__, target));
2052 KASSERT(log_entry != NULL,
2053 ("%s: After removing from head, the tailq was empty",
2054 __func__));
2055 }
2056 }
2057
2058 static inline int
tcp_log_copyout(struct sockopt * sopt,void * src,void * dst,size_t len)2059 tcp_log_copyout(struct sockopt *sopt, void *src, void *dst, size_t len)
2060 {
2061
2062 if (sopt->sopt_td != NULL)
2063 return (copyout(src, dst, len));
2064 bcopy(src, dst, len);
2065 return (0);
2066 }
2067
2068 static int
tcp_log_logs_to_buf(struct sockopt * sopt,struct tcp_log_stailq * log_tailqp,struct tcp_log_buffer ** end,int count)2069 tcp_log_logs_to_buf(struct sockopt *sopt, struct tcp_log_stailq *log_tailqp,
2070 struct tcp_log_buffer **end, int count)
2071 {
2072 struct tcp_log_buffer *out_entry;
2073 struct tcp_log_mem *log_entry;
2074 size_t entrysize;
2075 int error;
2076 #ifdef INVARIANTS
2077 int orig_count = count;
2078 #endif
2079
2080 /* Copy the data out. */
2081 error = 0;
2082 out_entry = (struct tcp_log_buffer *) sopt->sopt_val;
2083 STAILQ_FOREACH(log_entry, log_tailqp, tlm_queue) {
2084 count--;
2085 KASSERT(count >= 0,
2086 ("%s:%d: Exceeded expected count (%d) processing list %p",
2087 __func__, __LINE__, orig_count, log_tailqp));
2088
2089 #ifdef TCPLOG_DEBUG_COUNTERS
2090 counter_u64_add(tcp_log_que_copyout, 1);
2091 #endif
2092
2093 /*
2094 * Skip copying out the header if it isn't present.
2095 * Instead, copy out zeros (to ensure we don't leak info).
2096 * TODO: Make sure we truly do zero everything we don't
2097 * explicitly set.
2098 */
2099 if (log_entry->tlm_buf.tlb_eventflags & TLB_FLAG_HDR)
2100 entrysize = sizeof(struct tcp_log_buffer);
2101 else
2102 entrysize = offsetof(struct tcp_log_buffer, tlb_th);
2103 error = tcp_log_copyout(sopt, &log_entry->tlm_buf, out_entry,
2104 entrysize);
2105 if (error)
2106 break;
2107 if (!(log_entry->tlm_buf.tlb_eventflags & TLB_FLAG_HDR)) {
2108 error = tcp_log_copyout(sopt, zerobuf,
2109 ((uint8_t *)out_entry) + entrysize,
2110 sizeof(struct tcp_log_buffer) - entrysize);
2111 }
2112
2113 /*
2114 * Copy out the verbose bit, if needed. Either way,
2115 * increment the output pointer the correct amount.
2116 */
2117 if (log_entry->tlm_buf.tlb_eventflags & TLB_FLAG_VERBOSE) {
2118 error = tcp_log_copyout(sopt, &log_entry->tlm_v,
2119 out_entry->tlb_verbose,
2120 sizeof(struct tcp_log_verbose));
2121 if (error)
2122 break;
2123 out_entry = (struct tcp_log_buffer *)
2124 (((uint8_t *) (out_entry + 1)) +
2125 sizeof(struct tcp_log_verbose));
2126 } else
2127 out_entry++;
2128 }
2129 *end = out_entry;
2130 KASSERT(error || count == 0,
2131 ("%s:%d: Less than expected count (%d) processing list %p"
2132 " (%d remain)", __func__, __LINE__, orig_count,
2133 log_tailqp, count));
2134
2135 return (error);
2136 }
2137
2138 /*
2139 * Copy out the buffer. Note that we do incremental copying, so
2140 * sooptcopyout() won't work. However, the goal is to produce the same
2141 * end result as if we copied in the entire user buffer, updated it,
2142 * and then used sooptcopyout() to copy it out.
2143 *
2144 * NOTE: This should be called with a write lock on the PCB; however,
2145 * the function will drop it after it extracts the data from the TCPCB.
2146 */
2147 int
tcp_log_getlogbuf(struct sockopt * sopt,struct tcpcb * tp)2148 tcp_log_getlogbuf(struct sockopt *sopt, struct tcpcb *tp)
2149 {
2150 struct tcp_log_stailq log_tailq;
2151 struct tcp_log_mem *log_entry, *log_next;
2152 struct tcp_log_buffer *out_entry;
2153 struct inpcb *inp = tptoinpcb(tp);
2154 size_t outsize, entrysize;
2155 int error, outnum;
2156
2157 INP_WLOCK_ASSERT(inp);
2158
2159 /*
2160 * Determine which log entries will fit in the buffer. As an
2161 * optimization, skip this if all the entries will clearly fit
2162 * in the buffer. (However, get an exact size if we are using
2163 * INVARIANTS.)
2164 */
2165 #ifndef INVARIANTS
2166 if (sopt->sopt_valsize / (sizeof(struct tcp_log_buffer) +
2167 sizeof(struct tcp_log_verbose)) >= tp->t_lognum) {
2168 log_entry = STAILQ_LAST(&tp->t_logs, tcp_log_mem, tlm_queue);
2169 log_next = NULL;
2170 outsize = 0;
2171 outnum = tp->t_lognum;
2172 } else {
2173 #endif
2174 outsize = outnum = 0;
2175 log_entry = NULL;
2176 STAILQ_FOREACH(log_next, &tp->t_logs, tlm_queue) {
2177 entrysize = sizeof(struct tcp_log_buffer);
2178 if (log_next->tlm_buf.tlb_eventflags &
2179 TLB_FLAG_VERBOSE)
2180 entrysize += sizeof(struct tcp_log_verbose);
2181 if ((sopt->sopt_valsize - outsize) < entrysize)
2182 break;
2183 outsize += entrysize;
2184 outnum++;
2185 log_entry = log_next;
2186 }
2187 KASSERT(outsize <= sopt->sopt_valsize,
2188 ("%s: calculated output size (%zu) greater than available"
2189 "space (%zu)", __func__, outsize, sopt->sopt_valsize));
2190 #ifndef INVARIANTS
2191 }
2192 #endif
2193
2194 /*
2195 * Copy traditional sooptcopyout() behavior: if sopt->sopt_val
2196 * is NULL, silently skip the copy. However, in this case, we
2197 * will leave the list alone and return. Functionally, this
2198 * gives userspace a way to poll for an approximate buffer
2199 * size they will need to get the log entries.
2200 */
2201 if (sopt->sopt_val == NULL) {
2202 INP_WUNLOCK(inp);
2203 if (outsize == 0) {
2204 outsize = outnum * (sizeof(struct tcp_log_buffer) +
2205 sizeof(struct tcp_log_verbose));
2206 }
2207 if (sopt->sopt_valsize > outsize)
2208 sopt->sopt_valsize = outsize;
2209 return (0);
2210 }
2211
2212 /*
2213 * Break apart the list. We'll save the ones we want to copy
2214 * out locally and remove them from the TCPCB list. We can
2215 * then drop the INPCB lock while we do the copyout.
2216 *
2217 * There are roughly three cases:
2218 * 1. There was nothing to copy out. That's easy: drop the
2219 * lock and return.
2220 * 2. We are copying out the entire list. Again, that's easy:
2221 * move the whole list.
2222 * 3. We are copying out a partial list. That's harder. We
2223 * need to update the list book-keeping entries.
2224 */
2225 if (log_entry != NULL && log_next == NULL) {
2226 /* Move entire list. */
2227 KASSERT(outnum == tp->t_lognum,
2228 ("%s:%d: outnum (%d) should match tp->t_lognum (%d)",
2229 __func__, __LINE__, outnum, tp->t_lognum));
2230 log_tailq = tp->t_logs;
2231 tp->t_lognum = 0;
2232 STAILQ_INIT(&tp->t_logs);
2233 } else if (log_entry != NULL) {
2234 /* Move partial list. */
2235 KASSERT(outnum < tp->t_lognum,
2236 ("%s:%d: outnum (%d) not less than tp->t_lognum (%d)",
2237 __func__, __LINE__, outnum, tp->t_lognum));
2238 STAILQ_FIRST(&log_tailq) = STAILQ_FIRST(&tp->t_logs);
2239 STAILQ_FIRST(&tp->t_logs) = STAILQ_NEXT(log_entry, tlm_queue);
2240 KASSERT(STAILQ_NEXT(log_entry, tlm_queue) != NULL,
2241 ("%s:%d: tp->t_logs is unexpectedly shorter than expected"
2242 "(tp: %p, log_tailq: %p, outnum: %d, tp->t_lognum: %d)",
2243 __func__, __LINE__, tp, &log_tailq, outnum, tp->t_lognum));
2244 STAILQ_NEXT(log_entry, tlm_queue) = NULL;
2245 log_tailq.stqh_last = &STAILQ_NEXT(log_entry, tlm_queue);
2246 tp->t_lognum -= outnum;
2247 } else
2248 STAILQ_INIT(&log_tailq);
2249
2250 /* Drop the PCB lock. */
2251 INP_WUNLOCK(inp);
2252
2253 /* Copy the data out. */
2254 error = tcp_log_logs_to_buf(sopt, &log_tailq, &out_entry, outnum);
2255
2256 if (error) {
2257 /* Restore list */
2258 INP_WLOCK(inp);
2259 if ((inp->inp_flags & INP_DROPPED) == 0) {
2260 tp = intotcpcb(inp);
2261
2262 /* Merge the two lists. */
2263 STAILQ_CONCAT(&log_tailq, &tp->t_logs);
2264 tp->t_logs = log_tailq;
2265 tp->t_lognum += outnum;
2266 }
2267 INP_WUNLOCK(inp);
2268 } else {
2269 /* Sanity check entries */
2270 KASSERT(((caddr_t)out_entry - (caddr_t)sopt->sopt_val) ==
2271 outsize, ("%s: Actual output size (%zu) != "
2272 "calculated output size (%zu)", __func__,
2273 (size_t)((caddr_t)out_entry - (caddr_t)sopt->sopt_val),
2274 outsize));
2275
2276 /* Free the entries we just copied out. */
2277 STAILQ_FOREACH_SAFE(log_entry, &log_tailq, tlm_queue, log_next) {
2278 tcp_log_entry_refcnt_rem(log_entry);
2279 uma_zfree(tcp_log_zone, log_entry);
2280 }
2281 }
2282
2283 sopt->sopt_valsize = (size_t)((caddr_t)out_entry -
2284 (caddr_t)sopt->sopt_val);
2285 return (error);
2286 }
2287
2288 static void
tcp_log_free_queue(struct tcp_log_dev_queue * param)2289 tcp_log_free_queue(struct tcp_log_dev_queue *param)
2290 {
2291 struct tcp_log_dev_log_queue *entry;
2292
2293 KASSERT(param != NULL, ("%s: called with NULL param", __func__));
2294 if (param == NULL)
2295 return;
2296
2297 entry = (struct tcp_log_dev_log_queue *)param;
2298
2299 /* Free the entries. */
2300 tcp_log_free_entries(&entry->tldl_entries, &entry->tldl_count);
2301
2302 /* Free the buffer, if it is allocated. */
2303 if (entry->tldl_common.tldq_buf != NULL)
2304 free(entry->tldl_common.tldq_buf, M_TCPLOGDEV);
2305
2306 /* Free the queue entry. */
2307 free(entry, M_TCPLOGDEV);
2308 }
2309
2310 static struct tcp_log_common_header *
tcp_log_expandlogbuf(struct tcp_log_dev_queue * param)2311 tcp_log_expandlogbuf(struct tcp_log_dev_queue *param)
2312 {
2313 struct tcp_log_dev_log_queue *entry;
2314 struct tcp_log_header *hdr;
2315 uint8_t *end;
2316 struct sockopt sopt;
2317 int error;
2318
2319 entry = (struct tcp_log_dev_log_queue *)param;
2320
2321 /* Take a worst-case guess at space needs. */
2322 sopt.sopt_valsize = sizeof(struct tcp_log_header) +
2323 entry->tldl_count * (sizeof(struct tcp_log_buffer) +
2324 sizeof(struct tcp_log_verbose));
2325 hdr = malloc(sopt.sopt_valsize, M_TCPLOGDEV, M_NOWAIT);
2326 if (hdr == NULL) {
2327 #ifdef TCPLOG_DEBUG_COUNTERS
2328 counter_u64_add(tcp_log_que_fail5, entry->tldl_count);
2329 #endif
2330 return (NULL);
2331 }
2332 sopt.sopt_val = hdr + 1;
2333 sopt.sopt_valsize -= sizeof(struct tcp_log_header);
2334 sopt.sopt_td = NULL;
2335
2336 error = tcp_log_logs_to_buf(&sopt, &entry->tldl_entries,
2337 (struct tcp_log_buffer **)&end, entry->tldl_count);
2338 if (error) {
2339 free(hdr, M_TCPLOGDEV);
2340 return (NULL);
2341 }
2342
2343 /* Free the entries. */
2344 tcp_log_free_entries(&entry->tldl_entries, &entry->tldl_count);
2345 entry->tldl_count = 0;
2346
2347 memset(hdr, 0, sizeof(struct tcp_log_header));
2348 hdr->tlh_version = TCP_LOG_BUF_VER;
2349 hdr->tlh_type = TCP_LOG_DEV_TYPE_BBR;
2350 hdr->tlh_length = end - (uint8_t *)hdr;
2351 hdr->tlh_ie = entry->tldl_ie;
2352 hdr->tlh_af = entry->tldl_af;
2353 getboottime(&hdr->tlh_offset);
2354 strlcpy(hdr->tlh_id, entry->tldl_id, TCP_LOG_ID_LEN);
2355 strlcpy(hdr->tlh_tag, entry->tldl_tag, TCP_LOG_TAG_LEN);
2356 strlcpy(hdr->tlh_reason, entry->tldl_reason, TCP_LOG_REASON_LEN);
2357 return ((struct tcp_log_common_header *)hdr);
2358 }
2359
2360 /*
2361 * Queue the tcpcb's log buffer for transmission via the log buffer facility.
2362 *
2363 * NOTE: This should be called with a write lock on the PCB.
2364 *
2365 * how should be M_WAITOK or M_NOWAIT. If M_WAITOK, the function will drop
2366 * and reacquire the INP lock if it needs to do so.
2367 *
2368 * If force is false, this will only dump auto-logged sessions if
2369 * tcp_log_auto_all is true or if there is a log ID defined for the session.
2370 */
2371 int
tcp_log_dump_tp_logbuf(struct tcpcb * tp,char * reason,int how,bool force)2372 tcp_log_dump_tp_logbuf(struct tcpcb *tp, char *reason, int how, bool force)
2373 {
2374 struct tcp_log_dev_log_queue *entry;
2375 struct inpcb *inp = tptoinpcb(tp);
2376 #ifdef TCPLOG_DEBUG_COUNTERS
2377 int num_entries;
2378 #endif
2379
2380 INP_WLOCK_ASSERT(inp);
2381
2382 /* If there are no log entries, there is nothing to do. */
2383 if (tp->t_lognum == 0)
2384 return (0);
2385
2386 /* Check for a log ID. */
2387 if (tp->t_lib == NULL && (tp->t_flags2 & TF2_LOG_AUTO) &&
2388 !tcp_log_auto_all && !force) {
2389 struct tcp_log_mem *log_entry;
2390
2391 /*
2392 * We needed a log ID and none was found. Free the log entries
2393 * and return success. Also, cancel further logging. If the
2394 * session doesn't have a log ID by now, we'll assume it isn't
2395 * going to get one.
2396 */
2397 while ((log_entry = STAILQ_FIRST(&tp->t_logs)) != NULL)
2398 tcp_log_remove_log_head(tp, log_entry);
2399 KASSERT(tp->t_lognum == 0,
2400 ("%s: After freeing entries, tp->t_lognum=%d (expected 0)",
2401 __func__, tp->t_lognum));
2402 tp->_t_logstate = TCP_LOG_STATE_OFF;
2403 return (0);
2404 }
2405
2406 /*
2407 * Allocate memory. If we must wait, we'll need to drop the locks
2408 * and reacquire them (and do all the related business that goes
2409 * along with that).
2410 */
2411 entry = malloc(sizeof(struct tcp_log_dev_log_queue), M_TCPLOGDEV,
2412 M_NOWAIT);
2413 if (entry == NULL && (how & M_NOWAIT)) {
2414 #ifdef TCPLOG_DEBUG_COUNTERS
2415 counter_u64_add(tcp_log_que_fail3, 1);
2416 #endif
2417 return (ENOBUFS);
2418 }
2419 if (entry == NULL) {
2420 INP_WUNLOCK(inp);
2421 entry = malloc(sizeof(struct tcp_log_dev_log_queue),
2422 M_TCPLOGDEV, M_WAITOK);
2423 INP_WLOCK(inp);
2424 /*
2425 * Note that this check is slightly overly-restrictive in
2426 * that the TCB can survive either of these events.
2427 * However, there is currently not a good way to ensure
2428 * that is the case. So, if we hit this M_WAIT path, we
2429 * may end up dropping some entries. That seems like a
2430 * small price to pay for safety.
2431 */
2432 if (inp->inp_flags & INP_DROPPED) {
2433 free(entry, M_TCPLOGDEV);
2434 #ifdef TCPLOG_DEBUG_COUNTERS
2435 counter_u64_add(tcp_log_que_fail2, 1);
2436 #endif
2437 return (ECONNRESET);
2438 }
2439 tp = intotcpcb(inp);
2440 if (tp->t_lognum == 0) {
2441 free(entry, M_TCPLOGDEV);
2442 return (0);
2443 }
2444 }
2445
2446 /* Fill in the unique parts of the queue entry. */
2447 if (tp->t_lib != NULL) {
2448 strlcpy(entry->tldl_id, tp->t_lib->tlb_id, TCP_LOG_ID_LEN);
2449 strlcpy(entry->tldl_tag, tp->t_lib->tlb_tag, TCP_LOG_TAG_LEN);
2450 } else {
2451 strlcpy(entry->tldl_id, "UNKNOWN", TCP_LOG_ID_LEN);
2452 strlcpy(entry->tldl_tag, "UNKNOWN", TCP_LOG_TAG_LEN);
2453 }
2454 if (reason != NULL)
2455 strlcpy(entry->tldl_reason, reason, TCP_LOG_REASON_LEN);
2456 else
2457 strlcpy(entry->tldl_reason, "UNKNOWN", TCP_LOG_REASON_LEN);
2458 entry->tldl_ie = inp->inp_inc.inc_ie;
2459 if (inp->inp_inc.inc_flags & INC_ISIPV6)
2460 entry->tldl_af = AF_INET6;
2461 else
2462 entry->tldl_af = AF_INET;
2463 entry->tldl_entries = tp->t_logs;
2464 entry->tldl_count = tp->t_lognum;
2465
2466 /* Fill in the common parts of the queue entry. */
2467 entry->tldl_common.tldq_buf = NULL;
2468 entry->tldl_common.tldq_xform = tcp_log_expandlogbuf;
2469 entry->tldl_common.tldq_dtor = tcp_log_free_queue;
2470
2471 /* Clear the log data from the TCPCB. */
2472 #ifdef TCPLOG_DEBUG_COUNTERS
2473 num_entries = tp->t_lognum;
2474 #endif
2475 tp->t_lognum = 0;
2476 STAILQ_INIT(&tp->t_logs);
2477
2478 /* Add the entry. If no one is listening, free the entry. */
2479 if (tcp_log_dev_add_log((struct tcp_log_dev_queue *)entry)) {
2480 tcp_log_free_queue((struct tcp_log_dev_queue *)entry);
2481 #ifdef TCPLOG_DEBUG_COUNTERS
2482 counter_u64_add(tcp_log_que_fail1, num_entries);
2483 } else {
2484 counter_u64_add(tcp_log_queued, num_entries);
2485 #endif
2486 }
2487 return (0);
2488 }
2489
2490 /*
2491 * Queue the log_id_node's log buffers for transmission via the log buffer
2492 * facility.
2493 *
2494 * NOTE: This should be called with the bucket locked and referenced.
2495 *
2496 * how should be M_WAITOK or M_NOWAIT. If M_WAITOK, the function will drop
2497 * and reacquire the bucket lock if it needs to do so. (The caller must
2498 * ensure that the tln is no longer on any lists so no one else will mess
2499 * with this while the lock is dropped!)
2500 */
2501 static int
tcp_log_dump_node_logbuf(struct tcp_log_id_node * tln,char * reason,int how)2502 tcp_log_dump_node_logbuf(struct tcp_log_id_node *tln, char *reason, int how)
2503 {
2504 struct tcp_log_dev_log_queue *entry;
2505 struct tcp_log_id_bucket *tlb;
2506
2507 tlb = tln->tln_bucket;
2508 TCPID_BUCKET_LOCK_ASSERT(tlb);
2509 KASSERT(tlb->tlb_refcnt > 0,
2510 ("%s:%d: Called with unreferenced bucket (tln=%p, tlb=%p)",
2511 __func__, __LINE__, tln, tlb));
2512 KASSERT(tln->tln_closed,
2513 ("%s:%d: Called for node with tln_closed==false (tln=%p)",
2514 __func__, __LINE__, tln));
2515
2516 /* If there are no log entries, there is nothing to do. */
2517 if (tln->tln_count == 0)
2518 return (0);
2519
2520 /*
2521 * Allocate memory. If we must wait, we'll need to drop the locks
2522 * and reacquire them (and do all the related business that goes
2523 * along with that).
2524 */
2525 entry = malloc(sizeof(struct tcp_log_dev_log_queue), M_TCPLOGDEV,
2526 M_NOWAIT);
2527 if (entry == NULL && (how & M_NOWAIT))
2528 return (ENOBUFS);
2529 if (entry == NULL) {
2530 TCPID_BUCKET_UNLOCK(tlb);
2531 entry = malloc(sizeof(struct tcp_log_dev_log_queue),
2532 M_TCPLOGDEV, M_WAITOK);
2533 TCPID_BUCKET_LOCK(tlb);
2534 }
2535
2536 /* Fill in the common parts of the queue entry.. */
2537 entry->tldl_common.tldq_buf = NULL;
2538 entry->tldl_common.tldq_xform = tcp_log_expandlogbuf;
2539 entry->tldl_common.tldq_dtor = tcp_log_free_queue;
2540
2541 /* Fill in the unique parts of the queue entry. */
2542 strlcpy(entry->tldl_id, tlb->tlb_id, TCP_LOG_ID_LEN);
2543 strlcpy(entry->tldl_tag, tlb->tlb_tag, TCP_LOG_TAG_LEN);
2544 if (reason != NULL)
2545 strlcpy(entry->tldl_reason, reason, TCP_LOG_REASON_LEN);
2546 else
2547 strlcpy(entry->tldl_reason, "UNKNOWN", TCP_LOG_REASON_LEN);
2548 entry->tldl_ie = tln->tln_ie;
2549 entry->tldl_entries = tln->tln_entries;
2550 entry->tldl_count = tln->tln_count;
2551 entry->tldl_af = tln->tln_af;
2552
2553 /* Add the entry. If no one is listening, free the entry. */
2554 if (tcp_log_dev_add_log((struct tcp_log_dev_queue *)entry))
2555 tcp_log_free_queue((struct tcp_log_dev_queue *)entry);
2556
2557 return (0);
2558 }
2559
2560 /*
2561 * Queue the log buffers for all sessions in a bucket for transmissions via
2562 * the log buffer facility.
2563 *
2564 * NOTE: This should be called with a locked bucket; however, the function
2565 * will drop the lock.
2566 */
2567 #define LOCAL_SAVE 10
2568 static void
tcp_log_dumpbucketlogs(struct tcp_log_id_bucket * tlb,char * reason)2569 tcp_log_dumpbucketlogs(struct tcp_log_id_bucket *tlb, char *reason)
2570 {
2571 struct tcp_log_id_node local_entries[LOCAL_SAVE];
2572 struct inpcb *inp;
2573 struct tcpcb *tp;
2574 struct tcp_log_id_node *cur_tln, *prev_tln, *tmp_tln;
2575 int i, num_local_entries, tree_locked;
2576 bool expireq_locked;
2577
2578 TCPID_BUCKET_LOCK_ASSERT(tlb);
2579
2580 /*
2581 * Take a reference on the bucket to keep it from disappearing until
2582 * we are done.
2583 */
2584 TCPID_BUCKET_REF(tlb);
2585
2586 /*
2587 * We'll try to create these without dropping locks. However, we
2588 * might very well need to drop locks to get memory. If that's the
2589 * case, we'll save up to 10 on the stack, and sacrifice the rest.
2590 * (Otherwise, we need to worry about finding our place again in a
2591 * potentially changed list. It just doesn't seem worth the trouble
2592 * to do that.
2593 */
2594 expireq_locked = false;
2595 num_local_entries = 0;
2596 prev_tln = NULL;
2597 tree_locked = TREE_UNLOCKED;
2598 SLIST_FOREACH_SAFE(cur_tln, &tlb->tlb_head, tln_list, tmp_tln) {
2599 /*
2600 * If this isn't associated with a TCPCB, we can pull it off
2601 * the list now. We need to be careful that the expire timer
2602 * hasn't already taken ownership (tln_expiretime == SBT_MAX).
2603 * If so, we let the expire timer code free the data.
2604 */
2605 if (cur_tln->tln_closed) {
2606 no_inp:
2607 /*
2608 * Get the expireq lock so we can get a consistent
2609 * read of tln_expiretime and so we can remove this
2610 * from the expireq.
2611 */
2612 if (!expireq_locked) {
2613 TCPLOG_EXPIREQ_LOCK();
2614 expireq_locked = true;
2615 }
2616
2617 /*
2618 * We ignore entries with tln_expiretime == SBT_MAX.
2619 * The expire timer code already owns those.
2620 */
2621 KASSERT(cur_tln->tln_expiretime > (sbintime_t) 0,
2622 ("%s:%d: node on the expire queue without positive "
2623 "expire time", __func__, __LINE__));
2624 if (cur_tln->tln_expiretime == SBT_MAX) {
2625 prev_tln = cur_tln;
2626 continue;
2627 }
2628
2629 /* Remove the entry from the expireq. */
2630 STAILQ_REMOVE(&tcp_log_expireq_head, cur_tln,
2631 tcp_log_id_node, tln_expireq);
2632
2633 /* Remove the entry from the bucket. */
2634 if (prev_tln != NULL)
2635 SLIST_REMOVE_AFTER(prev_tln, tln_list);
2636 else
2637 SLIST_REMOVE_HEAD(&tlb->tlb_head, tln_list);
2638
2639 /*
2640 * Drop the INP and bucket reference counts. Due to
2641 * lock-ordering rules, we need to drop the expire
2642 * queue lock.
2643 */
2644 TCPLOG_EXPIREQ_UNLOCK();
2645 expireq_locked = false;
2646
2647 /* Drop the INP reference. */
2648 INP_WLOCK(cur_tln->tln_inp);
2649 if (!in_pcbrele_wlocked(cur_tln->tln_inp))
2650 INP_WUNLOCK(cur_tln->tln_inp);
2651
2652 if (tcp_log_unref_bucket(tlb, &tree_locked, NULL)) {
2653 #ifdef INVARIANTS
2654 panic("%s: Bucket refcount unexpectedly 0.",
2655 __func__);
2656 #endif
2657 /*
2658 * Recover as best we can: free the entry we
2659 * own.
2660 */
2661 tcp_log_free_entries(&cur_tln->tln_entries,
2662 &cur_tln->tln_count);
2663 uma_zfree(tcp_log_id_node_zone, cur_tln);
2664 goto done;
2665 }
2666
2667 if (tcp_log_dump_node_logbuf(cur_tln, reason,
2668 M_NOWAIT)) {
2669 /*
2670 * If we have sapce, save the entries locally.
2671 * Otherwise, free them.
2672 */
2673 if (num_local_entries < LOCAL_SAVE) {
2674 local_entries[num_local_entries] =
2675 *cur_tln;
2676 num_local_entries++;
2677 } else {
2678 tcp_log_free_entries(
2679 &cur_tln->tln_entries,
2680 &cur_tln->tln_count);
2681 }
2682 }
2683
2684 /* No matter what, we are done with the node now. */
2685 uma_zfree(tcp_log_id_node_zone, cur_tln);
2686
2687 /*
2688 * Because we removed this entry from the list, prev_tln
2689 * (which tracks the previous entry still on the tlb
2690 * list) remains unchanged.
2691 */
2692 continue;
2693 }
2694
2695 /*
2696 * If we get to this point, the session data is still held in
2697 * the TCPCB. So, we need to pull the data out of that.
2698 *
2699 * We will need to drop the expireq lock so we can lock the INP.
2700 * We can then try to extract the data the "easy" way. If that
2701 * fails, we'll save the log entries for later.
2702 */
2703 if (expireq_locked) {
2704 TCPLOG_EXPIREQ_UNLOCK();
2705 expireq_locked = false;
2706 }
2707
2708 /* Lock the INP and then re-check the state. */
2709 inp = cur_tln->tln_inp;
2710 INP_WLOCK(inp);
2711 /*
2712 * If we caught this while it was transitioning, the data
2713 * might have moved from the TCPCB to the tln (signified by
2714 * setting tln_closed to true. If so, treat this like an
2715 * inactive connection.
2716 */
2717 if (cur_tln->tln_closed) {
2718 /*
2719 * It looks like we may have caught this connection
2720 * while it was transitioning from active to inactive.
2721 * Treat this like an inactive connection.
2722 */
2723 INP_WUNLOCK(inp);
2724 goto no_inp;
2725 }
2726
2727 /*
2728 * Try to dump the data from the tp without dropping the lock.
2729 * If this fails, try to save off the data locally.
2730 */
2731 tp = cur_tln->tln_tp;
2732 if (tcp_log_dump_tp_logbuf(tp, reason, M_NOWAIT, true) &&
2733 num_local_entries < LOCAL_SAVE) {
2734 tcp_log_move_tp_to_node(tp,
2735 &local_entries[num_local_entries]);
2736 local_entries[num_local_entries].tln_closed = 1;
2737 KASSERT(local_entries[num_local_entries].tln_bucket ==
2738 tlb, ("%s: %d: bucket mismatch for node %p",
2739 __func__, __LINE__, cur_tln));
2740 num_local_entries++;
2741 }
2742
2743 INP_WUNLOCK(inp);
2744
2745 /*
2746 * We are goint to leave the current tln on the list. It will
2747 * become the previous tln.
2748 */
2749 prev_tln = cur_tln;
2750 }
2751
2752 /* Drop our locks, if any. */
2753 KASSERT(tree_locked == TREE_UNLOCKED,
2754 ("%s: %d: tree unexpectedly locked", __func__, __LINE__));
2755 switch (tree_locked) {
2756 case TREE_WLOCKED:
2757 TCPID_TREE_WUNLOCK();
2758 tree_locked = TREE_UNLOCKED;
2759 break;
2760 case TREE_RLOCKED:
2761 TCPID_TREE_RUNLOCK();
2762 tree_locked = TREE_UNLOCKED;
2763 break;
2764 }
2765 if (expireq_locked) {
2766 TCPLOG_EXPIREQ_UNLOCK();
2767 expireq_locked = false;
2768 }
2769
2770 /*
2771 * Try again for any saved entries. tcp_log_dump_node_logbuf() is
2772 * guaranteed to free the log entries within the node. And, since
2773 * the node itself is on our stack, we don't need to free it.
2774 */
2775 for (i = 0; i < num_local_entries; i++)
2776 tcp_log_dump_node_logbuf(&local_entries[i], reason, M_WAITOK);
2777
2778 /* Drop our reference. */
2779 if (!tcp_log_unref_bucket(tlb, &tree_locked, NULL))
2780 TCPID_BUCKET_UNLOCK(tlb);
2781
2782 done:
2783 /* Drop our locks, if any. */
2784 switch (tree_locked) {
2785 case TREE_WLOCKED:
2786 TCPID_TREE_WUNLOCK();
2787 break;
2788 case TREE_RLOCKED:
2789 TCPID_TREE_RUNLOCK();
2790 break;
2791 }
2792 if (expireq_locked)
2793 TCPLOG_EXPIREQ_UNLOCK();
2794 }
2795 #undef LOCAL_SAVE
2796
2797 /*
2798 * Queue the log buffers for all sessions in a bucket for transmissions via
2799 * the log buffer facility.
2800 *
2801 * NOTE: This should be called with a locked INP; however, the function
2802 * will drop the lock.
2803 */
2804 void
tcp_log_dump_tp_bucket_logbufs(struct tcpcb * tp,char * reason)2805 tcp_log_dump_tp_bucket_logbufs(struct tcpcb *tp, char *reason)
2806 {
2807 struct inpcb *inp = tptoinpcb(tp);
2808 struct tcp_log_id_bucket *tlb;
2809 int tree_locked;
2810
2811 /* Figure out our bucket and lock it. */
2812 INP_WLOCK_ASSERT(inp);
2813 tlb = tp->t_lib;
2814 if (tlb == NULL) {
2815 /*
2816 * No bucket; treat this like a request to dump a single
2817 * session's traces.
2818 */
2819 (void)tcp_log_dump_tp_logbuf(tp, reason, M_WAITOK, true);
2820 INP_WUNLOCK(inp);
2821 return;
2822 }
2823 TCPID_BUCKET_REF(tlb);
2824 INP_WUNLOCK(inp);
2825 TCPID_BUCKET_LOCK(tlb);
2826
2827 /* If we are the last reference, we have nothing more to do here. */
2828 tree_locked = TREE_UNLOCKED;
2829 if (tcp_log_unref_bucket(tlb, &tree_locked, NULL)) {
2830 switch (tree_locked) {
2831 case TREE_WLOCKED:
2832 TCPID_TREE_WUNLOCK();
2833 break;
2834 case TREE_RLOCKED:
2835 TCPID_TREE_RUNLOCK();
2836 break;
2837 }
2838 return;
2839 }
2840
2841 /* Turn this over to tcp_log_dumpbucketlogs() to finish the work. */
2842 tcp_log_dumpbucketlogs(tlb, reason);
2843 }
2844
2845 /*
2846 * Mark the end of a flow with the current stack. A stack can add
2847 * stack-specific info to this trace event by overriding this
2848 * function (see bbr_log_flowend() for example).
2849 */
2850 void
tcp_log_flowend(struct tcpcb * tp)2851 tcp_log_flowend(struct tcpcb *tp)
2852 {
2853 if (tp->_t_logstate != TCP_LOG_STATE_OFF) {
2854 struct socket *so = tptosocket(tp);
2855 TCP_LOG_EVENT(tp, NULL, &so->so_rcv, &so->so_snd,
2856 TCP_LOG_FLOWEND, 0, 0, NULL, false);
2857 }
2858 }
2859
2860 void
tcp_log_sendfile(struct socket * so,off_t offset,size_t nbytes,int flags)2861 tcp_log_sendfile(struct socket *so, off_t offset, size_t nbytes, int flags)
2862 {
2863 struct inpcb *inp;
2864 struct tcpcb *tp;
2865 #ifdef TCP_REQUEST_TRK
2866 struct tcp_sendfile_track *ent;
2867 int i, fnd;
2868 #endif
2869
2870 inp = sotoinpcb(so);
2871 KASSERT(inp != NULL, ("tcp_log_sendfile: inp == NULL"));
2872
2873 /* quick check to see if logging is enabled for this connection */
2874 tp = intotcpcb(inp);
2875 if ((inp->inp_flags & INP_DROPPED) ||
2876 (tp->_t_logstate == TCP_LOG_STATE_OFF)) {
2877 return;
2878 }
2879
2880 INP_WLOCK(inp);
2881 /* double check log state now that we have the lock */
2882 if (inp->inp_flags & INP_DROPPED)
2883 goto done;
2884 if (tcp_bblogging_on(tp)) {
2885 struct timeval tv;
2886 tcp_log_eventspecific_t log;
2887
2888 memset(&log, 0, sizeof(log));
2889 microuptime(&tv);
2890 log.u_sf.offset = offset;
2891 log.u_sf.length = nbytes;
2892 log.u_sf.flags = flags;
2893
2894 TCP_LOG_EVENTP(tp, NULL,
2895 &tptosocket(tp)->so_rcv,
2896 &tptosocket(tp)->so_snd,
2897 TCP_LOG_SENDFILE, 0, 0, &log, false, &tv);
2898 }
2899 #ifdef TCP_REQUEST_TRK
2900 if (tp->t_tcpreq_req == 0) {
2901 /* No http requests to track */
2902 goto done;
2903 }
2904 fnd = 0;
2905 if (tp->t_tcpreq_closed == 0) {
2906 /* No closed end req to track */
2907 goto skip_closed_req;
2908 }
2909 for(i = 0; i < MAX_TCP_TRK_REQ; i++) {
2910 /* Lets see if this one can be found */
2911 ent = &tp->t_tcpreq_info[i];
2912 if (ent->flags == TCP_TRK_TRACK_FLG_EMPTY) {
2913 /* Not used */
2914 continue;
2915 }
2916 if (ent->flags & TCP_TRK_TRACK_FLG_OPEN) {
2917 /* This pass does not consider open requests */
2918 continue;
2919 }
2920 if (ent->flags & TCP_TRK_TRACK_FLG_COMP) {
2921 /* Don't look at what we have completed */
2922 continue;
2923 }
2924 /* If we reach here its a allocated closed end request */
2925 if ((ent->start == offset) ||
2926 ((offset > ent->start) && (offset < ent->end))){
2927 /* Its within this request?? */
2928 fnd = 1;
2929 }
2930 if (fnd) {
2931 /*
2932 * It is at or past the end, its complete.
2933 */
2934 ent->flags |= TCP_TRK_TRACK_FLG_SEQV;
2935 /*
2936 * When an entry completes we can take (snd_una + sb_cc) and know where
2937 * the end of the range really is. Note that this works since two
2938 * requests must be sequential and sendfile now is complete for *this* request.
2939 * we must use sb_ccc since the data may still be in-flight in TLS.
2940 *
2941 * We always cautiously move the end_seq only if our calculations
2942 * show it happened (just in case sf has the call to here at the wrong
2943 * place). When we go COMP we will stop coming here and hopefully be
2944 * left with the correct end_seq.
2945 */
2946 if (SEQ_GT((tp->snd_una + so->so_snd.sb_ccc), ent->end_seq))
2947 ent->end_seq = tp->snd_una + so->so_snd.sb_ccc;
2948 if ((offset + nbytes) >= ent->end) {
2949 ent->flags |= TCP_TRK_TRACK_FLG_COMP;
2950 tcp_req_log_req_info(tp, ent, i, TCP_TRK_REQ_LOG_COMPLETE, offset, nbytes);
2951 } else {
2952 tcp_req_log_req_info(tp, ent, i, TCP_TRK_REQ_LOG_MOREYET, offset, nbytes);
2953 }
2954 /* We assume that sendfile never sends overlapping requests */
2955 goto done;
2956 }
2957 }
2958 skip_closed_req:
2959 if (!fnd) {
2960 /* Ok now lets look for open requests */
2961 for(i = 0; i < MAX_TCP_TRK_REQ; i++) {
2962 ent = &tp->t_tcpreq_info[i];
2963 if (ent->flags == TCP_TRK_TRACK_FLG_EMPTY) {
2964 /* Not used */
2965 continue;
2966 }
2967 if ((ent->flags & TCP_TRK_TRACK_FLG_OPEN) == 0)
2968 continue;
2969 /* If we reach here its an allocated open request */
2970 if (ent->start == offset) {
2971 /* It begins this request */
2972 ent->start_seq = tp->snd_una +
2973 tptosocket(tp)->so_snd.sb_ccc;
2974 ent->flags |= TCP_TRK_TRACK_FLG_SEQV;
2975 break;
2976 } else if (offset > ent->start) {
2977 ent->flags |= TCP_TRK_TRACK_FLG_SEQV;
2978 break;
2979 }
2980 }
2981 }
2982 #endif
2983 done:
2984 INP_WUNLOCK(inp);
2985 }
2986
2987 #ifdef DDB
2988 static void
db_print_indent(int indent)2989 db_print_indent(int indent)
2990 {
2991 int i;
2992
2993 for (i = 0; i < indent; i++)
2994 db_printf(" ");
2995 }
2996
2997 static void
db_print_tcphdr(struct tcp_log_buffer * tlm_buf)2998 db_print_tcphdr(struct tcp_log_buffer *tlm_buf)
2999 {
3000 struct sackblk sack;
3001 struct tcphdr *th;
3002 int cnt, i, j, opt, optlen, num_sacks;
3003 uint32_t val, ecr;
3004 uint16_t mss;
3005 uint16_t flags;
3006
3007 if ((tlm_buf->tlb_eventflags & TLB_FLAG_HDR) == 0) {
3008 return;
3009 }
3010 th = &tlm_buf->tlb_th;
3011 flags = tcp_get_flags(th);
3012 if (flags & TH_FIN) {
3013 db_printf("F");
3014 }
3015 if (flags & TH_SYN) {
3016 db_printf("S");
3017 }
3018 if (flags & TH_RST) {
3019 db_printf("R");
3020 }
3021 if (flags & TH_PUSH) {
3022 db_printf("P");
3023 }
3024 if (flags & TH_ACK) {
3025 db_printf(".");
3026 }
3027 if (flags & TH_URG) {
3028 db_printf("U");
3029 }
3030 if (flags & TH_ECE) {
3031 db_printf("E");
3032 }
3033 if (flags & TH_CWR) {
3034 db_printf("W");
3035 }
3036 if (flags & TH_AE) {
3037 db_printf("A");
3038 }
3039 db_printf(" %u:%u(%u)", ntohl(th->th_seq),
3040 ntohl(th->th_seq) + tlm_buf->tlb_len, tlm_buf->tlb_len);
3041 if (flags & TH_ACK) {
3042 db_printf(" ack %u", ntohl(th->th_ack));
3043 }
3044 db_printf(" win %u", ntohs(th->th_win));
3045 if (flags & TH_URG) {
3046 db_printf(" urg %u", ntohs(th->th_urp));
3047 }
3048 cnt = (th->th_off << 2) - sizeof(struct tcphdr);
3049 if (cnt > 0) {
3050 db_printf(" <");
3051 for (i = 0; i < cnt; i += optlen) {
3052 opt = tlm_buf->tlb_opts[i];
3053 if (opt == TCPOPT_EOL || opt == TCPOPT_NOP) {
3054 optlen = 1;
3055 } else {
3056 if (cnt - i < 2) {
3057 break;
3058 }
3059 optlen = tlm_buf->tlb_opts[i + 1];
3060 if (optlen < 2 || optlen > cnt - i) {
3061 break;
3062 }
3063 }
3064 if (i > 0) {
3065 db_printf(",");
3066 }
3067 switch (opt) {
3068 case TCPOPT_EOL:
3069 db_printf("eol");
3070 break;
3071 case TCPOPT_NOP:
3072 db_printf("nop");
3073 break;
3074 case TCPOPT_MAXSEG:
3075 if (optlen != TCPOLEN_MAXSEG) {
3076 break;
3077 }
3078 bcopy(tlm_buf->tlb_opts + i + 2, &mss,
3079 sizeof(uint16_t));
3080 db_printf("mss %u", ntohs(mss));
3081 break;
3082 case TCPOPT_WINDOW:
3083 if (optlen != TCPOLEN_WINDOW) {
3084 break;
3085 }
3086 db_printf("wscale %u",
3087 tlm_buf->tlb_opts[i + 2]);
3088 break;
3089 case TCPOPT_SACK_PERMITTED:
3090 if (optlen != TCPOLEN_SACK_PERMITTED) {
3091 break;
3092 }
3093 db_printf("sackOK");
3094 break;
3095 case TCPOPT_SACK:
3096 if (optlen == TCPOLEN_SACKHDR ||
3097 (optlen - 2) % TCPOLEN_SACK != 0) {
3098 break;
3099 }
3100 num_sacks = (optlen - 2) / TCPOLEN_SACK;
3101 db_printf("sack");
3102 for (j = 0; j < num_sacks; j++) {
3103 bcopy(tlm_buf->tlb_opts + i + 2 +
3104 j * TCPOLEN_SACK, &sack,
3105 TCPOLEN_SACK);
3106 db_printf(" %u:%u", ntohl(sack.start),
3107 ntohl(sack.end));
3108 }
3109 break;
3110 case TCPOPT_TIMESTAMP:
3111 if (optlen != TCPOLEN_TIMESTAMP) {
3112 break;
3113 }
3114 bcopy(tlm_buf->tlb_opts + i + 2, &val,
3115 sizeof(uint32_t));
3116 bcopy(tlm_buf->tlb_opts + i + 6, &ecr,
3117 sizeof(uint32_t));
3118 db_printf("TS val %u ecr %u", ntohl(val),
3119 ntohl(ecr));
3120 break;
3121 case TCPOPT_SIGNATURE:
3122 db_printf("md5");
3123 if (optlen > 2) {
3124 db_printf(" ");
3125 }
3126 for (j = 0; j < optlen - 2; j++) {
3127 db_printf("%02x",
3128 tlm_buf->tlb_opts[i + 2 + j]);
3129 }
3130 break;
3131 case TCPOPT_FAST_OPEN:
3132 db_printf("FO");
3133 if (optlen > 2) {
3134 db_printf(" ");
3135 }
3136 for (j = 0; j < optlen - 2; j++) {
3137 db_printf("%02x",
3138 tlm_buf->tlb_opts[i + 2 + j]);
3139 }
3140 break;
3141 default:
3142 db_printf("opt=%u len=%u", opt, optlen);
3143 break;
3144 }
3145 }
3146 db_printf(">");
3147 }
3148 }
3149 static void
db_print_pru(struct tcp_log_buffer * tlm_buf)3150 db_print_pru(struct tcp_log_buffer *tlm_buf)
3151 {
3152 switch (tlm_buf->tlb_flex1) {
3153 case PRU_ATTACH:
3154 db_printf("ATTACH");
3155 break;
3156 case PRU_DETACH:
3157 db_printf("DETACH");
3158 break;
3159 case PRU_BIND:
3160 db_printf("BIND");
3161 break;
3162 case PRU_LISTEN:
3163 db_printf("LISTEN");
3164 break;
3165 case PRU_CONNECT:
3166 db_printf("CONNECT");
3167 break;
3168 case PRU_ACCEPT:
3169 db_printf("ACCEPT");
3170 break;
3171 case PRU_DISCONNECT:
3172 db_printf("DISCONNECT");
3173 break;
3174 case PRU_SHUTDOWN:
3175 db_printf("SHUTDOWN");
3176 break;
3177 case PRU_RCVD:
3178 db_printf("RCVD");
3179 break;
3180 case PRU_SEND:
3181 db_printf("SEND");
3182 break;
3183 case PRU_ABORT:
3184 db_printf("ABORT");
3185 break;
3186 case PRU_CONTROL:
3187 db_printf("CONTROL");
3188 break;
3189 case PRU_SENSE:
3190 db_printf("SENSE");
3191 break;
3192 case PRU_RCVOOB:
3193 db_printf("RCVOOB");
3194 break;
3195 case PRU_SENDOOB:
3196 db_printf("SENDOOB");
3197 break;
3198 case PRU_SOCKADDR:
3199 db_printf("SOCKADDR");
3200 break;
3201 case PRU_PEERADDR:
3202 db_printf("PEERADDR");
3203 break;
3204 case PRU_CONNECT2:
3205 db_printf("CONNECT2");
3206 break;
3207 case PRU_FASTTIMO:
3208 db_printf("FASTTIMO");
3209 break;
3210 case PRU_SLOWTIMO:
3211 db_printf("SLOWTIMO");
3212 break;
3213 case PRU_PROTORCV:
3214 db_printf("PROTORCV");
3215 break;
3216 case PRU_PROTOSEND:
3217 db_printf("PROTOSEND");
3218 break;
3219 case PRU_SEND_EOF:
3220 db_printf("SEND_EOF");
3221 break;
3222 case PRU_SOSETLABEL:
3223 db_printf("SOSETLABEL");
3224 break;
3225 case PRU_CLOSE:
3226 db_printf("CLOSE");
3227 break;
3228 case PRU_FLUSH:
3229 db_printf("FLUSH");
3230 break;
3231 default:
3232 db_printf("Unknown PRU (%u)", tlm_buf->tlb_flex1);
3233 break;
3234 }
3235 if (tlm_buf->tlb_errno >= 0) {
3236 db_printf(", error: %d", tlm_buf->tlb_errno);
3237 }
3238 }
3239
3240 static void
db_print_rto(struct tcp_log_buffer * tlm_buf)3241 db_print_rto(struct tcp_log_buffer *tlm_buf)
3242 {
3243 tt_what what;
3244 tt_which which;
3245
3246 what = (tlm_buf->tlb_flex1 & 0xffffff00) >> 8;
3247 which = tlm_buf->tlb_flex1 & 0x000000ff;
3248 switch (what) {
3249 case TT_PROCESSING:
3250 db_printf("Processing ");
3251 break;
3252 case TT_PROCESSED:
3253 db_printf("Processed ");
3254 break;
3255 case TT_STARTING:
3256 db_printf("Starting ");
3257 break;
3258 case TT_STOPPING:
3259 db_printf("Stopping ");
3260 break;
3261 default:
3262 db_printf("Unknown operation (%u) for ", what);
3263 break;
3264 }
3265 switch (which) {
3266 case TT_REXMT:
3267 db_printf("Retransmission ");
3268 break;
3269 case TT_PERSIST:
3270 db_printf("Persist ");
3271 break;
3272 case TT_KEEP:
3273 db_printf("Keepalive ");
3274 break;
3275 case TT_2MSL:
3276 db_printf("2 MSL ");
3277 break;
3278 case TT_DELACK:
3279 db_printf("Delayed ACK ");
3280 break;
3281 default:
3282 db_printf("Unknown (%u) ", which);
3283 break;
3284 }
3285 db_printf("timer");
3286 if (what == TT_STARTING) {
3287 db_printf(": %u ms", tlm_buf->tlb_flex2);
3288 }
3289 }
3290
3291 static void
db_print_usersend(struct tcp_log_buffer * tlm_buf)3292 db_print_usersend(struct tcp_log_buffer *tlm_buf)
3293 {
3294 if ((tlm_buf->tlb_eventflags & TLB_FLAG_RXBUF) == 0) {
3295 return;
3296 }
3297 if ((tlm_buf->tlb_eventflags & TLB_FLAG_TXBUF) == 0) {
3298 return;
3299 }
3300 db_printf("usersend: rcv.acc: %u rcv.ccc: %u snd.acc: %u snd.ccc: %u",
3301 tlm_buf->tlb_rxbuf.tls_sb_acc, tlm_buf->tlb_rxbuf.tls_sb_ccc,
3302 tlm_buf->tlb_txbuf.tls_sb_acc, tlm_buf->tlb_txbuf.tls_sb_ccc);
3303 }
3304
3305 void
db_print_bblog_entries(struct tcp_log_stailq * log_entries,int indent)3306 db_print_bblog_entries(struct tcp_log_stailq *log_entries, int indent)
3307 {
3308 struct tcp_log_mem *log_entry;
3309 struct tcp_log_buffer *tlm_buf, *prev_tlm_buf;
3310 int64_t delta_t;
3311
3312 indent += 2;
3313 prev_tlm_buf = NULL;
3314 STAILQ_FOREACH(log_entry, log_entries, tlm_queue) {
3315 db_print_indent(indent);
3316 tlm_buf = &log_entry->tlm_buf;
3317 if (prev_tlm_buf == NULL) {
3318 db_printf(" 0.000 ");
3319 } else {
3320 delta_t = sbttoms(tvtosbt(tlm_buf->tlb_tv) -
3321 tvtosbt(prev_tlm_buf->tlb_tv));
3322 db_printf("+%u.%03u ", (uint32_t)(delta_t / 1000),
3323 (uint32_t)(delta_t % 1000));
3324 }
3325 switch (tlm_buf->tlb_eventid) {
3326 case TCP_LOG_IN:
3327 db_printf("< ");
3328 db_print_tcphdr(tlm_buf);
3329 break;
3330 case TCP_LOG_OUT:
3331 db_printf("> ");
3332 db_print_tcphdr(tlm_buf);
3333 break;
3334 case TCP_LOG_RTO:
3335 db_print_rto(tlm_buf);
3336 break;
3337 case TCP_LOG_PRU:
3338 db_print_pru(tlm_buf);
3339 break;
3340 case TCP_LOG_USERSEND:
3341 db_print_usersend(tlm_buf);
3342 break;
3343 default:
3344 break;
3345 }
3346 db_printf("\n");
3347 prev_tlm_buf = tlm_buf;
3348 if (db_pager_quit)
3349 break;
3350 }
3351 }
3352 #endif
3353