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 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 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 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 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 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 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 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 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 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 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 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 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 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 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 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 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 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 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 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 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 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 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 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 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 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 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 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 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 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 * 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 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 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 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 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 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 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 * 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 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 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 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 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 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 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 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 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 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 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 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 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