1 /*
2 * Copyright (c) 2018-2023 Apple Inc. All rights reserved.
3 *
4 * @APPLE_OSREFERENCE_LICENSE_HEADER_START@
5 *
6 * This file contains Original Code and/or Modifications of Original Code
7 * as defined in and that are subject to the Apple Public Source License
8 * Version 2.0 (the 'License'). You may not use this file except in
9 * compliance with the License. The rights granted to you under the License
10 * may not be used to create, or enable the creation or redistribution of,
11 * unlawful or unlicensed copies of an Apple operating system, or to
12 * circumvent, violate, or enable the circumvention or violation of, any
13 * terms of an Apple operating system software license agreement.
14 *
15 * Please obtain a copy of the License at
16 * http://www.opensource.apple.com/apsl/ and read it before using this file.
17 *
18 * The Original Code and all software distributed under the License are
19 * distributed on an 'AS IS' basis, WITHOUT WARRANTY OF ANY KIND, EITHER
20 * EXPRESS OR IMPLIED, AND APPLE HEREBY DISCLAIMS ALL SUCH WARRANTIES,
21 * INCLUDING WITHOUT LIMITATION, ANY WARRANTIES OF MERCHANTABILITY,
22 * FITNESS FOR A PARTICULAR PURPOSE, QUIET ENJOYMENT OR NON-INFRINGEMENT.
23 * Please see the License for the specific language governing rights and
24 * limitations under the License.
25 *
26 * @APPLE_OSREFERENCE_LICENSE_HEADER_END@
27 */
28
29 #include <sys/param.h>
30 #include <sys/protosw.h>
31 #include <sys/systm.h>
32 #include <sys/sysctl.h>
33
34 #include <kern/bits.h>
35
36 #include <netinet/ip.h>
37 #include <netinet/ip6.h>
38 #include <netinet/inp_log.h>
39
40 #if !TCPDEBUG
41 #define TCPSTATES
42 #endif /* TCPDEBUG */
43 #include <netinet/tcp_fsm.h>
44
45 #include <netinet/tcp_log.h>
46
47 SYSCTL_NODE(_net_inet_tcp, OID_AUTO, log, CTLFLAG_RW | CTLFLAG_LOCKED, 0,
48 "TCP logs");
49
50 #if (DEVELOPMENT || DEBUG)
51 #define TCP_LOG_ENABLE_DEFAULT \
52 (TLEF_CONNECTION | TLEF_DST_LOCAL | TLEF_DST_GW | \
53 TLEF_DROP_NECP | TLEF_DROP_PCB | TLEF_DROP_PKT | \
54 TLEF_SYN_RXMT)
55 #else /* (DEVELOPMENT || DEBUG) */
56 #define TCP_LOG_ENABLE_DEFAULT 0
57 #endif /* (DEVELOPMENT || DEBUG) */
58
59 uint32_t tcp_log_enable_flags = TCP_LOG_ENABLE_DEFAULT;
60 SYSCTL_UINT(_net_inet_tcp_log, OID_AUTO, enable,
61 CTLFLAG_RW | CTLFLAG_LOCKED, &tcp_log_enable_flags, 0, "");
62
63 /*
64 * The following is a help to describe the values of the flags
65 */
66 #define X(name, value, description, ...) #description ":" #value " "
67 SYSCTL_STRING(_net_inet_tcp_log, OID_AUTO, enable_usage, CTLFLAG_RD | CTLFLAG_LOCKED,
68 TCP_ENABLE_FLAG_LIST, 0, "");
69 #undef X
70
71 /*
72 * Values for tcp_log_port when TLEF_RTT is enabled:
73 * 0: log all TCP connections regardless of the port numbers
74 * 1 to 65535: log TCP connections with this local or foreign port
75 * other: do not log (same effect as as tcp_log_rtt == 0)
76 */
77 uint32_t tcp_log_port = 0;
78 SYSCTL_UINT(_net_inet_tcp_log, OID_AUTO, rtt_port, CTLFLAG_RW | CTLFLAG_LOCKED,
79 &tcp_log_port, 0, "");
80
81 /*
82 * Bitmap for tcp_log_thflags_if_family when TLEF_THF_XXX is enabled:
83 * 0: off
84 * other: only for interfaces with the corresponding interface family in the bitmap
85 */
86 #if (DEVELOPMENT || DEBUG)
87 #define TCP_LOG_THFLAGS_IF_FAMILY_DEFAULT (0xfffffffe & ~BIT(IFNET_FAMILY_LOOPBACK))
88 #else /* (DEVELOPMENT || DEBUG) */
89 #define TCP_LOG_THFLAGS_IF_FAMILY_DEFAULT 0
90 #endif /* (DEVELOPMENT || DEBUG) */
91
92 static uint64_t tcp_log_thflags_if_family = TCP_LOG_THFLAGS_IF_FAMILY_DEFAULT;
93 SYSCTL_QUAD(_net_inet_tcp_log, OID_AUTO, thflags_if_family,
94 CTLFLAG_RW | CTLFLAG_LOCKED, &tcp_log_thflags_if_family, "");
95
96
97 #define TCP_LOG_RATE_LIMIT 1000
98 static unsigned int tcp_log_rate_limit = TCP_LOG_RATE_LIMIT;
99 SYSCTL_UINT(_net_inet_tcp_log, OID_AUTO, rate_limit,
100 CTLFLAG_RW | CTLFLAG_LOCKED, &tcp_log_rate_limit, 0, "");
101
102 /* 1 minute by default */
103 #define TCP_LOG_RATE_DURATION 60
104 static unsigned int tcp_log_rate_duration = TCP_LOG_RATE_DURATION;
105 SYSCTL_UINT(_net_inet_tcp_log, OID_AUTO, rate_duration,
106 CTLFLAG_RW | CTLFLAG_LOCKED, &tcp_log_rate_duration, 0, "");
107
108 static unsigned long tcp_log_rate_max = 0;
109 SYSCTL_ULONG(_net_inet_tcp_log, OID_AUTO, rate_max,
110 CTLFLAG_RD | CTLFLAG_LOCKED, &tcp_log_rate_max, "");
111
112 static unsigned long tcp_log_rate_exceeded_total = 0;
113 SYSCTL_ULONG(_net_inet_tcp_log, OID_AUTO, rate_exceeded_total,
114 CTLFLAG_RD | CTLFLAG_LOCKED, &tcp_log_rate_exceeded_total, "");
115
116 static unsigned long tcp_log_rate_current = 0;
117 SYSCTL_ULONG(_net_inet_tcp_log, OID_AUTO, rate_current,
118 CTLFLAG_RD | CTLFLAG_LOCKED, &tcp_log_rate_current, "");
119
120 static bool tcp_log_rate_exceeded_logged = false;
121
122 static uint64_t tcp_log_current_period = 0;
123
124 #define ADDRESS_STR_LEN (MAX_IPv6_STR_LEN + 6)
125
126 #define TCP_LOG_COMMON_FMT \
127 "[%s:%u<->%s:%u] " \
128 "interface: %s " \
129 "(skipped: %lu)\n"
130
131 #define TCP_LOG_COMMON_ARGS \
132 laddr_buf, ntohs(local_port), faddr_buf, ntohs(foreign_port), \
133 ifp != NULL ? if_name(ifp) : "", \
134 tcp_log_rate_exceeded_total
135
136 #define TCP_LOG_COMMON_PCB_FMT \
137 TCP_LOG_COMMON_FMT \
138 "so_gencnt: %llu " \
139 "t_state: %s " \
140 "process: %s:%u "
141
142 #define TCP_LOG_COMMON_PCB_ARGS \
143 TCP_LOG_COMMON_ARGS, \
144 so != NULL ? so->so_gencnt : 0, \
145 tcpstates[tp->t_state], \
146 inp->inp_last_proc_name, so->last_pid
147
148 /*
149 * Returns true when above the rate limit
150 */
151 static bool
tcp_log_is_rate_limited(void)152 tcp_log_is_rate_limited(void)
153 {
154 uint64_t current_net_period = net_uptime();
155
156 /* When set to zero it means to reset to default */
157 if (tcp_log_rate_duration == 0) {
158 tcp_log_rate_duration = TCP_LOG_RATE_DURATION;
159 }
160 if (tcp_log_rate_limit == 0) {
161 tcp_log_rate_duration = TCP_LOG_RATE_LIMIT;
162 }
163
164 if (current_net_period > tcp_log_current_period + tcp_log_rate_duration) {
165 if (tcp_log_rate_current > tcp_log_rate_max) {
166 tcp_log_rate_max = tcp_log_rate_current;
167 }
168 tcp_log_current_period = current_net_period;
169 tcp_log_rate_current = 0;
170 tcp_log_rate_exceeded_logged = false;
171 }
172
173 tcp_log_rate_current += 1;
174
175 if (tcp_log_rate_current > (unsigned long) tcp_log_rate_limit) {
176 tcp_log_rate_exceeded_total += 1;
177 return true;
178 }
179
180 return false;
181 }
182
183 static void
tcp_log_inp_addresses(struct inpcb * inp,char * lbuf,socklen_t lbuflen,char * fbuf,socklen_t fbuflen)184 tcp_log_inp_addresses(struct inpcb *inp, char *lbuf, socklen_t lbuflen, char *fbuf, socklen_t fbuflen)
185 {
186 /*
187 * Ugly but %{private} does not work in the kernel version of os_log()
188 */
189 if (inp_log_privacy != 0) {
190 if (inp->inp_vflag & INP_IPV6) {
191 strlcpy(lbuf, "<IPv6-redacted>", lbuflen);
192 strlcpy(fbuf, "<IPv6-redacted>", fbuflen);
193 } else {
194 strlcpy(lbuf, "<IPv4-redacted>", lbuflen);
195 strlcpy(fbuf, "<IPv4-redacted>", fbuflen);
196 }
197 } else if (inp->inp_vflag & INP_IPV6) {
198 struct in6_addr addr6;
199
200 if (IN6_IS_ADDR_LINKLOCAL(&inp->in6p_laddr)) {
201 addr6 = inp->in6p_laddr;
202 addr6.s6_addr16[1] = 0;
203 inet_ntop(AF_INET6, (void *)&addr6, lbuf, lbuflen);
204 } else {
205 inet_ntop(AF_INET6, (void *)&inp->in6p_laddr, lbuf, lbuflen);
206 }
207
208 if (IN6_IS_ADDR_LINKLOCAL(&inp->in6p_faddr)) {
209 addr6 = inp->in6p_faddr;
210 addr6.s6_addr16[1] = 0;
211 inet_ntop(AF_INET6, (void *)&addr6, fbuf, fbuflen);
212 } else {
213 inet_ntop(AF_INET6, (void *)&inp->in6p_faddr, fbuf, fbuflen);
214 }
215 } else {
216 inet_ntop(AF_INET, (void *)&inp->inp_laddr.s_addr, lbuf, lbuflen);
217 inet_ntop(AF_INET, (void *)&inp->inp_faddr.s_addr, fbuf, fbuflen);
218 }
219 }
220
221 __attribute__((noinline))
222 void
tcp_log_rtt_info(const char * func_name,int line_no,struct tcpcb * tp)223 tcp_log_rtt_info(const char *func_name, int line_no, struct tcpcb *tp)
224 {
225 struct inpcb *inp = tp->t_inpcb;
226 struct socket *so = inp->inp_socket;
227 struct ifnet *ifp;
228 char laddr_buf[ADDRESS_STR_LEN];
229 char faddr_buf[ADDRESS_STR_LEN];
230 in_port_t local_port = inp->inp_lport;
231 in_port_t foreign_port = inp->inp_fport;
232
233 /* Do not log too much */
234 if (tcp_log_is_rate_limited()) {
235 return;
236 }
237
238 ifp = inp->inp_last_outifp != NULL ? inp->inp_last_outifp :
239 inp->inp_boundifp != NULL ? inp->inp_boundifp : NULL;
240
241 tcp_log_inp_addresses(inp, laddr_buf, sizeof(laddr_buf), faddr_buf, sizeof(faddr_buf));
242
243 os_log(OS_LOG_DEFAULT,
244 "tcp_rtt_info (%s:%d) "
245 TCP_LOG_COMMON_PCB_FMT
246 "base_rtt: %u ms rttcur: %u ms srtt: %u ms rttvar: %u ms rttmin: %u ms rxtcur: %u rxtshift: %u",
247 func_name, line_no,
248 TCP_LOG_COMMON_PCB_ARGS, get_base_rtt(tp),
249 tp->t_rttcur, tp->t_srtt >> TCP_RTT_SHIFT,
250 tp->t_rttvar >> TCP_RTTVAR_SHIFT,
251 tp->t_rttmin, tp->t_rxtcur, tp->t_rxtshift);
252 }
253
254 __attribute__((noinline))
255 void
tcp_log_rt_rtt(const char * func_name,int line_no,struct tcpcb * tp,struct rtentry * rt)256 tcp_log_rt_rtt(const char *func_name, int line_no, struct tcpcb *tp,
257 struct rtentry *rt)
258 {
259 struct inpcb *inp = tp->t_inpcb;
260 struct socket *so = inp->inp_socket;
261 struct ifnet *ifp;
262 char laddr_buf[ADDRESS_STR_LEN];
263 char faddr_buf[ADDRESS_STR_LEN];
264 in_port_t local_port = inp->inp_lport;
265 in_port_t foreign_port = inp->inp_fport;
266
267 /* Do not log too much */
268 if (tcp_log_is_rate_limited()) {
269 return;
270 }
271
272 ifp = inp->inp_last_outifp != NULL ? inp->inp_last_outifp :
273 inp->inp_boundifp != NULL ? inp->inp_boundifp : NULL;
274
275 tcp_log_inp_addresses(inp, laddr_buf, sizeof(laddr_buf), faddr_buf, sizeof(faddr_buf));
276
277 /*
278 * Log RTT values in milliseconds
279 */
280 os_log(OS_LOG_DEFAULT,
281 "tcp_rt_rtt (%s:%d) "
282 TCP_LOG_COMMON_PCB_FMT
283 "rt_rmx: RTV_RTT: %d ms rtt: %u ms rttvar: %u ms",
284 func_name, line_no,
285 TCP_LOG_COMMON_PCB_ARGS,
286 (rt->rt_rmx.rmx_locks & RTV_RTT),
287 rt->rt_rmx.rmx_rtt / (RTM_RTTUNIT / TCP_RETRANSHZ),
288 rt->rt_rmx.rmx_rttvar / (RTM_RTTUNIT / TCP_RETRANSHZ));
289 }
290
291 __attribute__((noinline))
292 void
tcp_log_rtt_change(const char * func_name,int line_no,struct tcpcb * tp,int old_srtt,int old_rttvar)293 tcp_log_rtt_change(const char *func_name, int line_no, struct tcpcb *tp,
294 int old_srtt, int old_rttvar)
295 {
296 int srtt_diff;
297 int rttvar_diff;
298
299 srtt_diff = ABS(tp->t_srtt - old_srtt) >> TCP_RTT_SHIFT;
300 rttvar_diff =
301 ABS((tp->t_rttvar - old_rttvar) >> TCP_RTTVAR_SHIFT);
302 if (srtt_diff >= 1000 || rttvar_diff >= 500) {
303 struct inpcb *inp = tp->t_inpcb;
304 struct socket *so = inp->inp_socket;
305 struct ifnet *ifp;
306 char laddr_buf[ADDRESS_STR_LEN];
307 char faddr_buf[ADDRESS_STR_LEN];
308 in_port_t local_port = inp->inp_lport;
309 in_port_t foreign_port = inp->inp_fport;
310
311 /* Do not log too much */
312 if (tcp_log_is_rate_limited()) {
313 return;
314 }
315
316 ifp = inp->inp_last_outifp != NULL ? inp->inp_last_outifp :
317 inp->inp_boundifp != NULL ? inp->inp_boundifp : NULL;
318
319 tcp_log_inp_addresses(inp, laddr_buf, sizeof(laddr_buf), faddr_buf, sizeof(faddr_buf));
320
321 os_log(OS_LOG_DEFAULT,
322 "tcp_rtt_change (%s:%d) "
323 TCP_LOG_COMMON_PCB_FMT
324 "srtt: %u ms old_rtt: %u ms "
325 "rttvar: %u old_rttvar: %u ms ",
326 func_name, line_no,
327 TCP_LOG_COMMON_PCB_ARGS,
328 tp->t_srtt >> TCP_RTT_SHIFT,
329 old_srtt >> TCP_RTT_SHIFT,
330 tp->t_rttvar >> TCP_RTTVAR_SHIFT,
331 old_rttvar >> TCP_RTTVAR_SHIFT);
332 }
333 }
334
335 __attribute__((noinline))
336 void
tcp_log_keepalive(const char * func_name,int line_no,struct tcpcb * tp,int32_t idle_time)337 tcp_log_keepalive(const char *func_name, int line_no, struct tcpcb *tp,
338 int32_t idle_time)
339 {
340 struct inpcb *inp = tp->t_inpcb;
341 struct socket *so = inp->inp_socket;
342 struct ifnet *ifp;
343 char laddr_buf[ADDRESS_STR_LEN];
344 char faddr_buf[ADDRESS_STR_LEN];
345 in_port_t local_port = inp->inp_lport;
346 in_port_t foreign_port = inp->inp_fport;
347
348 /* Do not log too much */
349 if (tcp_log_is_rate_limited()) {
350 return;
351 }
352
353 ifp = inp->inp_last_outifp != NULL ? inp->inp_last_outifp :
354 inp->inp_boundifp != NULL ? inp->inp_boundifp : NULL;
355
356 tcp_log_inp_addresses(inp, laddr_buf, sizeof(laddr_buf), faddr_buf, sizeof(faddr_buf));
357
358 os_log(OS_LOG_DEFAULT,
359 "tcp_keepalive (%s:%d) "
360 TCP_LOG_COMMON_PCB_FMT
361 "snd_una: %u snd_max: %u "
362 "SO_KA: %d RSTALL: %d TFOPRB: %d idle_time: %u "
363 "KIDLE: %d KINTV: %d KCNT: %d",
364 func_name, line_no,
365 TCP_LOG_COMMON_PCB_ARGS,
366 tp->snd_una, tp->snd_max,
367 tp->t_inpcb->inp_socket->so_options & SO_KEEPALIVE,
368 tp->t_flagsext & TF_DETECT_READSTALL,
369 tp->t_tfo_probe_state == TFO_PROBE_PROBING,
370 idle_time,
371 TCP_CONN_KEEPIDLE(tp), TCP_CONN_KEEPINTVL(tp),
372 TCP_CONN_KEEPCNT(tp));
373 }
374
375 #define P_MS(ms, shift) ((ms) >> (shift)), (((ms) * 1000) >> (shift)) % 1000
376
377 __attribute__((noinline))
378 void
tcp_log_connection(struct tcpcb * tp,const char * event,int error)379 tcp_log_connection(struct tcpcb *tp, const char *event, int error)
380 {
381 struct inpcb *inp;
382 struct socket *so;
383 struct ifnet *ifp;
384 char laddr_buf[ADDRESS_STR_LEN];
385 char faddr_buf[ADDRESS_STR_LEN];
386 in_port_t local_port;
387 in_port_t foreign_port;
388
389 if (tp == NULL || tp->t_inpcb == NULL || tp->t_inpcb->inp_socket == NULL || event == NULL) {
390 return;
391 }
392
393 /* Do not log too much */
394 if (tcp_log_is_rate_limited()) {
395 return;
396 }
397 inp = tp->t_inpcb;
398 so = inp->inp_socket;
399
400 local_port = inp->inp_lport;
401 foreign_port = inp->inp_fport;
402
403 ifp = inp->inp_last_outifp != NULL ? inp->inp_last_outifp :
404 inp->inp_boundifp != NULL ? inp->inp_boundifp : NULL;
405
406 tcp_log_inp_addresses(inp, laddr_buf, sizeof(laddr_buf), faddr_buf, sizeof(faddr_buf));
407
408 #define TCP_LOG_CONNECT_FMT \
409 "tcp %s: " \
410 TCP_LOG_COMMON_PCB_FMT \
411 "SYN in/out: %u/%u " \
412 "bytes in/out: %llu/%llu " \
413 "pkts in/out: %llu/%llu " \
414 "rtt: %u.%u ms " \
415 "rttvar: %u.%u ms " \
416 "base_rtt: %u ms " \
417 "error: %d " \
418 "so_error: %d " \
419 "svc/tc: %u " \
420 "flow: 0x%x"
421
422 #define TCP_LOG_CONNECT_ARGS \
423 event, \
424 TCP_LOG_COMMON_PCB_ARGS, \
425 tp->t_syn_rcvd, tp->t_syn_sent, \
426 inp->inp_stat->rxbytes, inp->inp_stat->txbytes, \
427 inp->inp_stat->rxpackets, inp->inp_stat->txpackets, \
428 P_MS(tp->t_srtt, TCP_RTT_SHIFT), \
429 P_MS(tp->t_rttvar, TCP_RTTVAR_SHIFT), \
430 get_base_rtt(tp), \
431 error, \
432 so->so_error, \
433 (so->so_flags1 & SOF1_TC_NET_SERV_TYPE) ? so->so_netsvctype : so->so_traffic_class, \
434 inp->inp_flowhash
435
436 if (so->so_head == NULL) {
437 os_log(OS_LOG_DEFAULT, TCP_LOG_CONNECT_FMT,
438 TCP_LOG_CONNECT_ARGS);
439 } else {
440 #define TCP_LOG_CONN_Q_FMT \
441 "so_qlimit: %d "\
442 "so_qlen: %d "\
443 "so_incqlen: %d "
444
445 #define TCP_LOG_CONN_Q_ARGS \
446 so->so_head->so_qlimit, \
447 so->so_head->so_qlen, \
448 so->so_head->so_incqlen
449
450 os_log(OS_LOG_DEFAULT, TCP_LOG_CONNECT_FMT "\n" TCP_LOG_CONN_Q_FMT,
451 TCP_LOG_CONNECT_ARGS, TCP_LOG_CONN_Q_ARGS);
452 #undef TCP_LOG_CONN_Q_FMT
453 #undef TCP_LOG_CONN_Q_ARGS
454 }
455 #undef TCP_LOG_CONNECT_FMT
456 #undef TCP_LOG_CONNECT_ARGS
457 }
458
459 __attribute__((noinline))
460 void
tcp_log_listen(struct tcpcb * tp,int error)461 tcp_log_listen(struct tcpcb *tp, int error)
462 {
463 struct inpcb *inp = tp->t_inpcb;
464 struct socket *so = inp->inp_socket;
465 struct ifnet *ifp;
466 char laddr_buf[ADDRESS_STR_LEN];
467 char faddr_buf[ADDRESS_STR_LEN];
468 in_port_t local_port;
469 in_port_t foreign_port;
470
471 if (tp == NULL || tp->t_inpcb == NULL || tp->t_inpcb->inp_socket == NULL) {
472 return;
473 }
474
475 /* Do not log too much */
476 if (tcp_log_is_rate_limited()) {
477 return;
478 }
479 inp = tp->t_inpcb;
480 so = inp->inp_socket;
481
482 local_port = inp->inp_lport;
483 foreign_port = inp->inp_fport;
484
485 ifp = inp->inp_last_outifp != NULL ? inp->inp_last_outifp :
486 inp->inp_boundifp != NULL ? inp->inp_boundifp : NULL;
487
488 tcp_log_inp_addresses(inp, laddr_buf, sizeof(laddr_buf), faddr_buf, sizeof(faddr_buf));
489
490 #define TCP_LOG_LISTEN_FMT \
491 "tcp listen: " \
492 TCP_LOG_COMMON_PCB_FMT \
493 "so_qlimit: %d "\
494 "error: %d " \
495 "so_error: %d " \
496 "svc/tc: %u"
497
498 #define TCP_LOG_LISTEN_ARGS \
499 TCP_LOG_COMMON_PCB_ARGS, \
500 so->so_qlimit, \
501 error, \
502 so->so_error, \
503 (so->so_flags1 & SOF1_TC_NET_SERV_TYPE) ? so->so_netsvctype : so->so_traffic_class
504
505 os_log(OS_LOG_DEFAULT, TCP_LOG_LISTEN_FMT,
506 TCP_LOG_LISTEN_ARGS);
507 #undef TCP_LOG_LISTEN_FMT
508 #undef TCP_LOG_LISTEN_ARGS
509 }
510
511 static const char *
tcp_connection_client_accurate_ecn_state_to_string(tcp_connection_client_accurate_ecn_state_t state)512 tcp_connection_client_accurate_ecn_state_to_string(tcp_connection_client_accurate_ecn_state_t state)
513 {
514 switch (state) {
515 #define ECN_STATE_TO_STRING(_s, _str) \
516 case tcp_connection_client_accurate_ecn_##_s: { \
517 return _str; \
518 }
519 ECN_STATE_TO_STRING(invalid, "Invalid")
520 ECN_STATE_TO_STRING(feature_disabled, "Disabled")
521 ECN_STATE_TO_STRING(feature_enabled, "Enabled")
522 ECN_STATE_TO_STRING(negotiation_blackholed, "Blackholed")
523 ECN_STATE_TO_STRING(ace_bleaching_detected, "ACE bleaching")
524 ECN_STATE_TO_STRING(negotiation_success, "Capable")
525 ECN_STATE_TO_STRING(negotiation_success_ect_mangling_detected, "ECT mangling")
526 ECN_STATE_TO_STRING(negotiation_success_ect_bleaching_detected, "ECT bleaching")
527 #undef ECN_STATE_TO_STRING
528 case tcp_connection_client_classic_ecn_available:
529 return "Classic ECN";
530 case tcp_connection_client_ecn_not_available:
531 return "Unavailable";
532 }
533 return "Unknown";
534 }
535
536 static const char *
tcp_connection_server_accurate_ecn_state_to_string(tcp_connection_server_accurate_ecn_state_t state)537 tcp_connection_server_accurate_ecn_state_to_string(tcp_connection_server_accurate_ecn_state_t state)
538 {
539 switch (state) {
540 #define ECN_STATE_TO_STRING(_s, _str) \
541 case tcp_connection_server_accurate_ecn_##_s: { \
542 return _str; \
543 }
544 ECN_STATE_TO_STRING(invalid, "Invalid")
545 ECN_STATE_TO_STRING(feature_disabled, "Disabled")
546 ECN_STATE_TO_STRING(feature_enabled, "Enabled")
547 ECN_STATE_TO_STRING(requested, "Requested")
548 ECN_STATE_TO_STRING(negotiation_blackholed, "Blackholed")
549 ECN_STATE_TO_STRING(ace_bleaching_detected, "ACE bleaching")
550 ECN_STATE_TO_STRING(negotiation_success, "Capable")
551 ECN_STATE_TO_STRING(negotiation_success_ect_mangling_detected, "ECT mangling")
552 ECN_STATE_TO_STRING(negotiation_success_ect_bleaching_detected, "ECT bleaching")
553 #undef ECN_STATE_TO_STRING
554 case tcp_connection_server_no_ecn_requested:
555 return "Not requested";
556 case tcp_connection_server_classic_ecn_requested:
557 return "Classic ECN requested";
558 }
559 return "Unknown";
560 }
561
562 __attribute__((noinline))
563 void
tcp_log_connection_summary(struct tcpcb * tp)564 tcp_log_connection_summary(struct tcpcb *tp)
565 {
566 struct inpcb *inp;
567 struct socket *so;
568 struct ifnet *ifp;
569 uint32_t conntime = 0;
570 uint32_t duration = 0;
571 char laddr_buf[ADDRESS_STR_LEN];
572 char faddr_buf[ADDRESS_STR_LEN];
573 in_port_t local_port;
574 in_port_t foreign_port;
575
576 if (tp == NULL || tp->t_inpcb == NULL || tp->t_inpcb->inp_socket == NULL) {
577 return;
578 }
579
580 /* Do not log too much */
581 if (tcp_log_is_rate_limited()) {
582 return;
583 }
584 inp = tp->t_inpcb;
585 so = inp->inp_socket;
586
587 local_port = inp->inp_lport;
588 foreign_port = inp->inp_fport;
589
590 /* Make sure the summary is logged once */
591 if (inp->inp_flags2 & INP2_LOGGED_SUMMARY) {
592 return;
593 }
594 inp->inp_flags2 |= INP2_LOGGED_SUMMARY;
595
596 /*
597 * t_connect_time is the time when the connection started on
598 * the first SYN.
599 *
600 * t_starttime is when the three way handshake was completed.
601 */
602 if (tp->t_connect_time > 0) {
603 duration = tcp_now - tp->t_connect_time;
604
605 if (tp->t_starttime > 0) {
606 conntime = tp->t_starttime - tp->t_connect_time;
607 }
608 }
609
610 ifp = inp->inp_last_outifp != NULL ? inp->inp_last_outifp :
611 inp->inp_boundifp != NULL ? inp->inp_boundifp : NULL;
612
613 tcp_log_inp_addresses(inp, laddr_buf, sizeof(laddr_buf), faddr_buf, sizeof(faddr_buf));
614
615 /*
616 * Need to use 2 log messages because the size of the summary
617 */
618
619 #define TCP_LOG_CONNECTION_SUMMARY_FMT \
620 "tcp_connection_summary " \
621 TCP_LOG_COMMON_PCB_FMT \
622 "Duration: %u.%03u sec " \
623 "Conn_Time: %u.%03u sec " \
624 "bytes in/out: %llu/%llu " \
625 "pkts in/out: %llu/%llu " \
626 "pkt rxmit: %u " \
627 "ooo pkts: %u dup bytes in: %u ACKs delayed: %u delayed ACKs sent: %u\n" \
628 "rtt: %u.%03u ms " \
629 "rttvar: %u.%03u ms " \
630 "base rtt: %u ms " \
631 "so_error: %d " \
632 "svc/tc: %u " \
633 "flow: 0x%x"
634
635 #define TCP_LOG_CONNECTION_SUMMARY_ARGS \
636 TCP_LOG_COMMON_PCB_ARGS, \
637 duration / TCP_RETRANSHZ, duration % TCP_RETRANSHZ, \
638 conntime / TCP_RETRANSHZ, conntime % TCP_RETRANSHZ, \
639 inp->inp_stat->rxbytes, inp->inp_stat->txbytes, \
640 inp->inp_stat->rxpackets, inp->inp_stat->txpackets, \
641 tp->t_stat.rxmitpkts, \
642 tp->t_rcvoopack, tp->t_stat.rxduplicatebytes, tp->t_stat.acks_delayed, tp->t_stat.delayed_acks_sent, \
643 P_MS(tp->t_srtt, TCP_RTT_SHIFT), \
644 P_MS(tp->t_rttvar, TCP_RTTVAR_SHIFT), \
645 get_base_rtt(tp), \
646 so->so_error, \
647 (so->so_flags1 & SOF1_TC_NET_SERV_TYPE) ? so->so_netsvctype : so->so_traffic_class, \
648 inp->inp_flowhash
649
650 os_log(OS_LOG_DEFAULT, TCP_LOG_CONNECTION_SUMMARY_FMT,
651 TCP_LOG_CONNECTION_SUMMARY_ARGS);
652 #undef TCP_LOG_CONNECTION_SUMMARY_FMT
653 #undef TCP_LOG_CONNECTION_SUMMARY_ARGS
654
655 #define TCP_LOG_CONNECTION_SUMMARY_FMT \
656 "tcp_connection_summary " \
657 TCP_LOG_COMMON_PCB_FMT \
658 "flowctl: %lluus (%llux) " \
659 "SYN in/out: %u/%u " \
660 "FIN in/out: %u/%u " \
661 "RST in/out: %u/%u " \
662 "AccECN (client/server): %s/%s\n" \
663
664 #define TCP_LOG_CONNECTION_SUMMARY_ARGS \
665 TCP_LOG_COMMON_PCB_ARGS, \
666 inp->inp_fadv_total_time, \
667 inp->inp_fadv_cnt, \
668 tp->t_syn_rcvd, tp->t_syn_sent, \
669 tp->t_fin_rcvd, tp->t_fin_sent, \
670 tp->t_rst_rcvd, tp->t_rst_sent, \
671 tcp_connection_client_accurate_ecn_state_to_string(tp->t_client_accecn_state), \
672 tcp_connection_server_accurate_ecn_state_to_string(tp->t_server_accecn_state)
673
674 os_log(OS_LOG_DEFAULT, TCP_LOG_CONNECTION_SUMMARY_FMT,
675 TCP_LOG_CONNECTION_SUMMARY_ARGS);
676 #undef TCP_LOG_CONNECTION_SUMMARY_FMT
677 #undef TCP_LOG_CONNECTION_SUMMARY_ARGS
678 }
679
680 __attribute__((noinline))
681 static bool
tcp_log_pkt_addresses(void * hdr,struct tcphdr * th,bool outgoing,char * lbuf,socklen_t lbuflen,char * fbuf,socklen_t fbuflen)682 tcp_log_pkt_addresses(void *hdr, struct tcphdr *th, bool outgoing,
683 char *lbuf, socklen_t lbuflen, char *fbuf, socklen_t fbuflen)
684 {
685 bool isipv6;
686 uint8_t thflags;
687
688 isipv6 = (((struct ip *)hdr)->ip_v == 6);
689 thflags = th->th_flags;
690
691 if (isipv6) {
692 struct ip6_hdr *ip6 = (struct ip6_hdr *)hdr;
693
694 if (memcmp(&ip6->ip6_src, &in6addr_loopback, sizeof(struct in6_addr)) == 0 ||
695 memcmp(&ip6->ip6_dst, &in6addr_loopback, sizeof(struct in6_addr)) == 0) {
696 if (!(tcp_log_enable_flags & TLEF_DST_LOOPBACK)) {
697 return false;
698 }
699 }
700
701 if (inp_log_privacy != 0) {
702 strlcpy(lbuf, "<IPv6-redacted>", lbuflen);
703 strlcpy(fbuf, "<IPv6-redacted>", fbuflen);
704 } else if (outgoing) {
705 inet_ntop(AF_INET6, &ip6->ip6_src, lbuf, lbuflen);
706 inet_ntop(AF_INET6, &ip6->ip6_dst, fbuf, fbuflen);
707 } else {
708 inet_ntop(AF_INET6, &ip6->ip6_dst, lbuf, lbuflen);
709 inet_ntop(AF_INET6, &ip6->ip6_src, fbuf, fbuflen);
710 }
711 } else {
712 struct ip *ip = (struct ip *)hdr;
713
714 if (ntohl(ip->ip_src.s_addr) == INADDR_LOOPBACK ||
715 ntohl(ip->ip_dst.s_addr) == INADDR_LOOPBACK) {
716 if (!(tcp_log_enable_flags & TLEF_DST_LOOPBACK)) {
717 return false;
718 }
719 }
720
721 if (inp_log_privacy != 0) {
722 strlcpy(lbuf, "<IPv4-redacted>", lbuflen);
723 strlcpy(fbuf, "<IPv4-redacted>", fbuflen);
724 } else if (outgoing) {
725 inet_ntop(AF_INET, (void *)&ip->ip_src.s_addr, lbuf, lbuflen);
726 inet_ntop(AF_INET, (void *)&ip->ip_dst.s_addr, fbuf, fbuflen);
727 } else {
728 inet_ntop(AF_INET, (void *)&ip->ip_dst.s_addr, lbuf, lbuflen);
729 inet_ntop(AF_INET, (void *)&ip->ip_src.s_addr, fbuf, fbuflen);
730 }
731 }
732 return true;
733 }
734
735 /*
736 * Note: currently only used in the input path
737 */
738 __attribute__((noinline))
739 void
tcp_log_drop_pcb(void * hdr,struct tcphdr * th,struct tcpcb * tp,bool outgoing,const char * reason)740 tcp_log_drop_pcb(void *hdr, struct tcphdr *th, struct tcpcb *tp, bool outgoing, const char *reason)
741 {
742 struct inpcb *inp;
743 struct socket *so;
744 struct ifnet *ifp;
745 char laddr_buf[ADDRESS_STR_LEN];
746 char faddr_buf[ADDRESS_STR_LEN];
747 in_port_t local_port;
748 in_port_t foreign_port;
749 const char *direction = "";
750
751 if (tp == NULL) {
752 return;
753 }
754 inp = tp->t_inpcb;
755 if (inp == NULL) {
756 return;
757 }
758 so = inp->inp_socket;
759 if (so == NULL) {
760 return;
761 }
762
763 /* Do not log common drops after the connection termination is logged */
764 if ((inp->inp_flags2 & INP2_LOGGED_SUMMARY) && ((so->so_state & SS_NOFDREF) ||
765 (so->so_flags & SOF_DEFUNCT) || (so->so_state & SS_CANTRCVMORE))) {
766 return;
767 }
768
769 /* Do not log too much */
770 if (tcp_log_is_rate_limited()) {
771 return;
772 }
773
774 /* Use the packet addresses when in the data path */
775 if (hdr != NULL && th != NULL) {
776 if (outgoing) {
777 local_port = th->th_sport;
778 foreign_port = th->th_dport;
779 direction = "outgoing ";
780 } else {
781 local_port = th->th_dport;
782 foreign_port = th->th_sport;
783 direction = "incoming ";
784 }
785 (void) tcp_log_pkt_addresses(hdr, th, outgoing, laddr_buf, sizeof(laddr_buf), faddr_buf, sizeof(faddr_buf));
786 } else {
787 local_port = inp->inp_lport;
788 foreign_port = inp->inp_fport;
789 tcp_log_inp_addresses(inp, laddr_buf, sizeof(laddr_buf), faddr_buf, sizeof(faddr_buf));
790 }
791
792 ifp = inp->inp_last_outifp != NULL ? inp->inp_last_outifp :
793 inp->inp_boundifp != NULL ? inp->inp_boundifp : NULL;
794
795 #define TCP_LOG_DROP_PCB_FMT \
796 "tcp drop %s" \
797 TCP_LOG_COMMON_PCB_FMT \
798 "t_state: %s " \
799 "so_error: %d " \
800 "reason: %s"
801
802 #define TCP_LOG_DROP_PCB_ARGS \
803 direction, \
804 TCP_LOG_COMMON_PCB_ARGS, \
805 tcpstates[tp->t_state], \
806 so->so_error, \
807 reason
808
809 os_log(OS_LOG_DEFAULT, TCP_LOG_DROP_PCB_FMT,
810 TCP_LOG_DROP_PCB_ARGS);
811 #undef TCP_LOG_DROP_PCB_FMT
812 #undef TCP_LOG_DROP_PCB_ARGS
813 }
814
815 #define TCP_LOG_TH_FLAGS_COMMON_FMT \
816 "tcp control %s " \
817 "%s" \
818 "%s" \
819 "%s" \
820 "%s" \
821 TCP_LOG_COMMON_FMT
822
823 #define TCP_LOG_TH_FLAGS_COMMON_ARGS \
824 outgoing ? "outgoing" : "incoming", \
825 thflags & TH_SYN ? "SYN " : "", \
826 thflags & TH_FIN ? "FIN " : "", \
827 thflags & TH_RST ? "RST " : "", \
828 thflags & TH_ACK ? "ACK " : "", \
829 TCP_LOG_COMMON_ARGS
830
831 static bool
should_log_th_flags(uint8_t thflags,struct tcpcb * tp,bool outgoing,struct ifnet * ifp)832 should_log_th_flags(uint8_t thflags, struct tcpcb *tp, bool outgoing, struct ifnet *ifp)
833 {
834 /*
835 * Check logging is enabled for interface for TCP control packets
836 *
837 * Note: the type of tcp_log_thflags_if_family is uint64_t but we
838 * access its value as bit string so we have to pay extra care to avoid
839 * out of bound access
840 */
841 if (ifp != NULL && (ifp->if_family >= (sizeof(tcp_log_thflags_if_family) << 3) ||
842 !bitstr_test((bitstr_t *)&tcp_log_thflags_if_family, ifp->if_family))) {
843 return false;
844 }
845 /*
846 * Log when seeing 3 SYN retransmissions of more on a TCP PCB
847 */
848 if (tp != NULL &&
849 ((thflags & TH_SYN) && (tcp_log_enable_flags & TLEF_SYN_RXMT) &&
850 ((outgoing && tp->t_syn_sent > 3) || (!outgoing && tp->t_syn_rcvd > 3)))) {
851 return true;
852 }
853 /*
854 * Log control packet when enabled
855 */
856 if ((((thflags & TH_SYN) && (tcp_log_enable_flags & TLEF_THF_SYN)) ||
857 ((thflags & TH_FIN) && (tcp_log_enable_flags & TLEF_THF_FIN)) ||
858 ((thflags & TH_RST) && (tcp_log_enable_flags & TLEF_THF_RST)))) {
859 return true;
860 }
861 return false;
862 }
863
864 __attribute__((noinline))
865 void
tcp_log_th_flags(void * hdr,struct tcphdr * th,struct tcpcb * tp,bool outgoing,struct ifnet * ifp)866 tcp_log_th_flags(void *hdr, struct tcphdr *th, struct tcpcb *tp, bool outgoing, struct ifnet *ifp)
867 {
868 struct inpcb *inp = tp->t_inpcb;
869 struct socket *so = inp != NULL ? inp->inp_socket : NULL;
870 char laddr_buf[ADDRESS_STR_LEN];
871 char faddr_buf[ADDRESS_STR_LEN];
872 in_port_t local_port;
873 in_port_t foreign_port;
874 uint8_t thflags;
875
876 if (hdr == NULL || th == NULL) {
877 return;
878 }
879
880 thflags = th->th_flags;
881
882 if (should_log_th_flags(thflags, tp, outgoing, ifp) == false) {
883 return;
884 }
885
886 if (outgoing) {
887 local_port = th->th_sport;
888 foreign_port = th->th_dport;
889 } else {
890 local_port = th->th_dport;
891 foreign_port = th->th_sport;
892 }
893 if (!tcp_log_pkt_addresses(hdr, th, outgoing, laddr_buf, sizeof(laddr_buf), faddr_buf, sizeof(faddr_buf))) {
894 return;
895 }
896
897 /* Do not log too much */
898 if (tcp_log_is_rate_limited()) {
899 return;
900 }
901
902 /*
903 * When no PCB or socket just log the packet
904 */
905 if (tp == NULL || so == NULL || inp == NULL) {
906 #define TCP_LOG_TH_FLAGS_NO_PCB_FMT \
907 TCP_LOG_TH_FLAGS_COMMON_FMT \
908 TCP_LOG_COMMON_FMT
909 #define TCP_LOG_TH_FLAGS_NO_PCB_ARGS \
910 TCP_LOG_TH_FLAGS_COMMON_ARGS, \
911 TCP_LOG_COMMON_ARGS
912
913 os_log(OS_LOG_DEFAULT, TCP_LOG_TH_FLAGS_NO_PCB_FMT,
914 TCP_LOG_TH_FLAGS_NO_PCB_ARGS);
915 #undef TCP_LOG_TH_FLAGS_NO_PCB_FMT
916 #undef TCP_LOG_TH_FLAGS_NO_PCB_ARGS
917 } else {
918 #define TCP_LOG_TH_FLAGS_PCB_FMT \
919 TCP_LOG_TH_FLAGS_COMMON_FMT \
920 TCP_LOG_COMMON_PCB_FMT \
921 "SYN in/out: %u/%u "
922
923 #define TCP_LOG_TH_FLAGS_PCB_ARGS \
924 TCP_LOG_TH_FLAGS_COMMON_ARGS, \
925 TCP_LOG_COMMON_PCB_ARGS, \
926 tp->t_syn_rcvd, tp->t_syn_sent
927
928 os_log(OS_LOG_DEFAULT, TCP_LOG_TH_FLAGS_PCB_FMT,
929 TCP_LOG_TH_FLAGS_PCB_ARGS);
930 #undef TCP_LOG_TH_FLAGS_PCB_FMT
931 #undef TCP_LOG_TH_FLAGS_PCB_ARGS
932 }
933 }
934
935 __attribute__((noinline))
936 void
tcp_log_drop_pkt(void * hdr,struct tcphdr * th,struct ifnet * ifp,const char * reason)937 tcp_log_drop_pkt(void *hdr, struct tcphdr *th, struct ifnet *ifp, const char *reason)
938 {
939 char laddr_buf[ADDRESS_STR_LEN];
940 char faddr_buf[ADDRESS_STR_LEN];
941 in_port_t local_port;
942 in_port_t foreign_port;
943 uint8_t thflags;
944 bool outgoing = false; /* This is only for incoming packets */
945
946 if (hdr == NULL || th == NULL) {
947 return;
948 }
949
950 local_port = th->th_dport;
951 foreign_port = th->th_sport;
952 thflags = th->th_flags;
953
954 if (should_log_th_flags(thflags, NULL, outgoing, ifp) == false) {
955 return;
956 }
957
958 if (!tcp_log_pkt_addresses(hdr, th, outgoing, laddr_buf, sizeof(laddr_buf), faddr_buf, sizeof(faddr_buf))) {
959 return;
960 }
961
962 /* Do not log too much */
963 if (tcp_log_is_rate_limited()) {
964 return;
965 }
966
967 #define TCP_LOG_DROP_PKT_FMT \
968 "tcp drop incoming control packet " \
969 TCP_LOG_TH_FLAGS_COMMON_FMT \
970 "reason: %s"
971
972 #define TCP_LOG_DROP_PKT_ARGS \
973 TCP_LOG_TH_FLAGS_COMMON_ARGS, \
974 reason != NULL ? reason : ""
975
976 os_log(OS_LOG_DEFAULT, TCP_LOG_DROP_PKT_FMT,
977 TCP_LOG_DROP_PKT_ARGS);
978 #undef TCP_LOG_DROP_PKT_FMT
979 #undef TCP_LOG_DROP_PKT_ARGS
980 }
981
982 __attribute__((noinline))
983 void
tcp_log_message(const char * func_name,int line_no,struct tcpcb * tp,const char * format,...)984 tcp_log_message(const char *func_name, int line_no, struct tcpcb *tp, const char *format, ...)
985 {
986 struct inpcb *inp;
987 struct socket *so;
988 struct ifnet *ifp;
989 char laddr_buf[ADDRESS_STR_LEN];
990 char faddr_buf[ADDRESS_STR_LEN];
991 in_port_t local_port;
992 in_port_t foreign_port;
993 char message[256];
994
995 if (tp == NULL || tp->t_inpcb == NULL || tp->t_inpcb->inp_socket == NULL) {
996 return;
997 }
998
999 /* Do not log too much */
1000 if (tcp_log_is_rate_limited()) {
1001 return;
1002 }
1003 inp = tp->t_inpcb;
1004 so = inp->inp_socket;
1005
1006 local_port = inp->inp_lport;
1007 foreign_port = inp->inp_fport;
1008
1009 ifp = inp->inp_last_outifp != NULL ? inp->inp_last_outifp :
1010 inp->inp_boundifp != NULL ? inp->inp_boundifp : NULL;
1011
1012 tcp_log_inp_addresses(inp, laddr_buf, sizeof(laddr_buf), faddr_buf, sizeof(faddr_buf));
1013
1014 va_list ap;
1015 va_start(ap, format);
1016 vsnprintf(message, sizeof(message), format, ap);
1017 va_end(ap);
1018
1019 #define TCP_LOG_MESSAGE_FMT \
1020 "tcp (%s:%d) " \
1021 TCP_LOG_COMMON_PCB_FMT \
1022 "bytes in/out: %llu/%llu " \
1023 "pkts in/out: %llu/%llu " \
1024 "%s"
1025
1026 #define TCP_LOG_MESSAGE_ARGS \
1027 func_name, line_no, \
1028 TCP_LOG_COMMON_PCB_ARGS, \
1029 inp->inp_stat->rxbytes, inp->inp_stat->txbytes, \
1030 inp->inp_stat->rxpackets, inp->inp_stat->txpackets, \
1031 message
1032
1033 os_log(OS_LOG_DEFAULT, TCP_LOG_MESSAGE_FMT,
1034 TCP_LOG_MESSAGE_ARGS);
1035 #undef TCP_LOG_MESSAGE_FMT
1036 #undef TCP_LOG_MESSAGE_ARGS
1037 }
1038
1039 #if SKYWALK
1040 __attribute__((noinline))
1041 void
tcp_log_fsw_flow(const char * func_name,int line_no,struct tcpcb * tp,const char * format,...)1042 tcp_log_fsw_flow(const char *func_name, int line_no, struct tcpcb *tp, const char *format, ...)
1043 {
1044 struct inpcb *inp;
1045 struct socket *so;
1046 struct ifnet *ifp;
1047 char laddr_buf[ADDRESS_STR_LEN];
1048 char faddr_buf[ADDRESS_STR_LEN];
1049 in_port_t local_port;
1050 in_port_t foreign_port;
1051 uuid_string_t flow_uuid_str;
1052 char message[256];
1053
1054 if (tp == NULL || tp->t_inpcb == NULL || tp->t_inpcb->inp_socket == NULL) {
1055 return;
1056 }
1057
1058 /* Do not log too much */
1059 if (tcp_log_is_rate_limited()) {
1060 return;
1061 }
1062 inp = tp->t_inpcb;
1063 so = inp->inp_socket;
1064
1065 local_port = inp->inp_lport;
1066 foreign_port = inp->inp_fport;
1067
1068 ifp = inp->inp_last_outifp != NULL ? inp->inp_last_outifp :
1069 inp->inp_boundifp != NULL ? inp->inp_boundifp : NULL;
1070
1071 tcp_log_inp_addresses(inp, laddr_buf, sizeof(laddr_buf), faddr_buf, sizeof(faddr_buf));
1072
1073 uuid_unparse_upper(tp->t_flow_uuid, flow_uuid_str);
1074
1075 va_list ap;
1076 va_start(ap, format);
1077 vsnprintf(message, sizeof(message), format, ap);
1078 va_end(ap);
1079
1080 #define TCP_LOG_FSW_FLOW_MESSAGE_FMT \
1081 "tcp (%s:%d) " \
1082 TCP_LOG_COMMON_PCB_FMT \
1083 "flow %s %s"
1084
1085 #define TCP_LOG_FSW_FLOW_MESSAGE_ARGS \
1086 func_name, line_no, \
1087 TCP_LOG_COMMON_PCB_ARGS, \
1088 flow_uuid_str, \
1089 message
1090
1091 os_log(OS_LOG_DEFAULT, TCP_LOG_FSW_FLOW_MESSAGE_FMT,
1092 TCP_LOG_FSW_FLOW_MESSAGE_ARGS);
1093 #undef TCP_LOG_FSW_FLOW_MESSAGE_FMT
1094 #undef TCP_LOG_FSW_FLOW_MESSAGE_ARGS
1095 }
1096 #endif /* SKYWALK */
1097
1098 void
tcp_log_state_change(struct tcpcb * tp,int new_state)1099 tcp_log_state_change(struct tcpcb *tp, int new_state)
1100 {
1101 struct inpcb *inp;
1102 struct socket *so;
1103 struct ifnet *ifp;
1104 uint32_t conntime = 0;
1105 uint32_t duration = 0;
1106 char laddr_buf[ADDRESS_STR_LEN];
1107 char faddr_buf[ADDRESS_STR_LEN];
1108 in_port_t local_port;
1109 in_port_t foreign_port;
1110
1111 if (tp == NULL || tp->t_inpcb == NULL || tp->t_inpcb->inp_socket == NULL) {
1112 return;
1113 }
1114 if (new_state == tp->t_state) {
1115 return;
1116 }
1117
1118 /* Do not log too much */
1119 if (tcp_log_is_rate_limited()) {
1120 return;
1121 }
1122
1123 inp = tp->t_inpcb;
1124 so = inp->inp_socket;
1125
1126 local_port = inp->inp_lport;
1127 foreign_port = inp->inp_fport;
1128
1129 /*
1130 * t_connect_time is the time when the connection started on
1131 * the first SYN.
1132 *
1133 * t_starttime is when the three way handshake was completed.
1134 */
1135 if (tp->t_connect_time > 0) {
1136 duration = tcp_now - tp->t_connect_time;
1137
1138 if (tp->t_starttime > 0) {
1139 conntime = tp->t_starttime - tp->t_connect_time;
1140 }
1141 }
1142
1143 ifp = inp->inp_last_outifp != NULL ? inp->inp_last_outifp :
1144 inp->inp_boundifp != NULL ? inp->inp_boundifp : NULL;
1145
1146 tcp_log_inp_addresses(inp, laddr_buf, sizeof(laddr_buf), faddr_buf, sizeof(faddr_buf));
1147
1148 #define TCP_LOG_STATE_FMT \
1149 "tcp_state_changed " \
1150 TCP_LOG_COMMON_PCB_FMT
1151
1152 #define TCP_LOG_STATE_ARGS \
1153 TCP_LOG_COMMON_ARGS, \
1154 so != NULL ? so->so_gencnt : 0, \
1155 tcpstates[new_state], \
1156 inp->inp_last_proc_name, so->last_pid
1157
1158 os_log(OS_LOG_DEFAULT, TCP_LOG_STATE_FMT,
1159 TCP_LOG_STATE_ARGS);
1160 #undef TCP_LOG_STATE_FMT
1161 #undef TCP_LOG_STATE_ARGS
1162 }
1163
1164 __attribute__((noinline))
1165 void
tcp_log_output(const char * func_name,int line_no,struct tcpcb * tp,const char * format,...)1166 tcp_log_output(const char *func_name, int line_no, struct tcpcb *tp, const char *format, ...)
1167 {
1168 struct inpcb *inp;
1169 struct socket *so;
1170 struct ifnet *ifp;
1171 char laddr_buf[ADDRESS_STR_LEN];
1172 char faddr_buf[ADDRESS_STR_LEN];
1173 in_port_t local_port;
1174 in_port_t foreign_port;
1175 char message[256];
1176
1177 if (tp == NULL || tp->t_inpcb == NULL || tp->t_inpcb->inp_socket == NULL) {
1178 return;
1179 }
1180 /* Log only when fron send() or connect() */
1181 if ((tp->t_flagsext & TF_USR_OUTPUT) == 0) {
1182 return;
1183 }
1184 /* Do not log too much */
1185 if (tcp_log_is_rate_limited()) {
1186 return;
1187 }
1188 inp = tp->t_inpcb;
1189 so = inp->inp_socket;
1190
1191 local_port = inp->inp_lport;
1192 foreign_port = inp->inp_fport;
1193
1194 ifp = inp->inp_last_outifp != NULL ? inp->inp_last_outifp :
1195 inp->inp_boundifp != NULL ? inp->inp_boundifp : NULL;
1196
1197 tcp_log_inp_addresses(inp, laddr_buf, sizeof(laddr_buf), faddr_buf, sizeof(faddr_buf));
1198
1199 va_list ap;
1200 va_start(ap, format);
1201 vsnprintf(message, sizeof(message), format, ap);
1202 va_end(ap);
1203
1204 #define TCP_LOG_MESSAGE_FMT \
1205 "tcp (%s:%d) " \
1206 TCP_LOG_COMMON_PCB_FMT \
1207 "bytes in/out: %llu/%llu " \
1208 "pkts in/out: %llu/%llu " \
1209 "rxmit pkts/bytes: %u/%u" \
1210 "%s"
1211
1212 #define TCP_LOG_MESSAGE_ARGS \
1213 func_name, line_no, \
1214 TCP_LOG_COMMON_PCB_ARGS, \
1215 inp->inp_stat->rxbytes, inp->inp_stat->txbytes, \
1216 inp->inp_stat->rxpackets, inp->inp_stat->txpackets, \
1217 tp->t_stat.rxmitpkts, tp->t_stat.txretransmitbytes, \
1218 message
1219
1220 os_log(OS_LOG_DEFAULT, TCP_LOG_MESSAGE_FMT,
1221 TCP_LOG_MESSAGE_ARGS);
1222 #undef TCP_LOG_MESSAGE_FMT
1223 #undef TCP_LOG_MESSAGE_ARGS
1224 }
1225