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
421 #define TCP_LOG_CONNECT_ARGS \
422 event, \
423 TCP_LOG_COMMON_PCB_ARGS, \
424 tp->t_syn_rcvd, tp->t_syn_sent, \
425 inp->inp_stat->rxbytes, inp->inp_stat->txbytes, \
426 inp->inp_stat->rxpackets, inp->inp_stat->txpackets, \
427 P_MS(tp->t_srtt, TCP_RTT_SHIFT), \
428 P_MS(tp->t_rttvar, TCP_RTTVAR_SHIFT), \
429 get_base_rtt(tp), \
430 error, \
431 so->so_error, \
432 (so->so_flags1 & SOF1_TC_NET_SERV_TYPE) ? so->so_netsvctype : so->so_traffic_class
433
434 if (so->so_head == NULL) {
435 os_log(OS_LOG_DEFAULT, TCP_LOG_CONNECT_FMT,
436 TCP_LOG_CONNECT_ARGS);
437 } else {
438 #define TCP_LOG_CONN_Q_FMT \
439 "so_qlimit: %d "\
440 "so_qlen: %d "\
441 "so_incqlen: %d "
442
443 #define TCP_LOG_CONN_Q_ARGS \
444 so->so_head->so_qlimit, \
445 so->so_head->so_qlen, \
446 so->so_head->so_incqlen
447
448 os_log(OS_LOG_DEFAULT, TCP_LOG_CONNECT_FMT "\n" TCP_LOG_CONN_Q_FMT,
449 TCP_LOG_CONNECT_ARGS, TCP_LOG_CONN_Q_ARGS);
450 #undef TCP_LOG_CONN_Q_FMT
451 #undef TCP_LOG_CONN_Q_ARGS
452 }
453 #undef TCP_LOG_CONNECT_FMT
454 #undef TCP_LOG_CONNECT_ARGS
455 }
456
457 __attribute__((noinline))
458 void
tcp_log_listen(struct tcpcb * tp,int error)459 tcp_log_listen(struct tcpcb *tp, int error)
460 {
461 struct inpcb *inp = tp->t_inpcb;
462 struct socket *so = inp->inp_socket;
463 struct ifnet *ifp;
464 char laddr_buf[ADDRESS_STR_LEN];
465 char faddr_buf[ADDRESS_STR_LEN];
466 in_port_t local_port;
467 in_port_t foreign_port;
468
469 if (tp == NULL || tp->t_inpcb == NULL || tp->t_inpcb->inp_socket == NULL) {
470 return;
471 }
472
473 /* Do not log too much */
474 if (tcp_log_is_rate_limited()) {
475 return;
476 }
477 inp = tp->t_inpcb;
478 so = inp->inp_socket;
479
480 local_port = inp->inp_lport;
481 foreign_port = inp->inp_fport;
482
483 ifp = inp->inp_last_outifp != NULL ? inp->inp_last_outifp :
484 inp->inp_boundifp != NULL ? inp->inp_boundifp : NULL;
485
486 tcp_log_inp_addresses(inp, laddr_buf, sizeof(laddr_buf), faddr_buf, sizeof(faddr_buf));
487
488 #define TCP_LOG_LISTEN_FMT \
489 "tcp listen: " \
490 TCP_LOG_COMMON_PCB_FMT \
491 "so_qlimit: %d "\
492 "error: %d " \
493 "so_error: %d " \
494 "svc/tc: %u"
495
496 #define TCP_LOG_LISTEN_ARGS \
497 TCP_LOG_COMMON_PCB_ARGS, \
498 so->so_qlimit, \
499 error, \
500 so->so_error, \
501 (so->so_flags1 & SOF1_TC_NET_SERV_TYPE) ? so->so_netsvctype : so->so_traffic_class
502
503 os_log(OS_LOG_DEFAULT, TCP_LOG_LISTEN_FMT,
504 TCP_LOG_LISTEN_ARGS);
505 #undef TCP_LOG_LISTEN_FMT
506 #undef TCP_LOG_LISTEN_ARGS
507 }
508
509 static const char *
tcp_connection_client_accurate_ecn_state_to_string(tcp_connection_client_accurate_ecn_state_t state)510 tcp_connection_client_accurate_ecn_state_to_string(tcp_connection_client_accurate_ecn_state_t state)
511 {
512 switch (state) {
513 #define ECN_STATE_TO_STRING(_s, _str) \
514 case tcp_connection_client_accurate_ecn_##_s: { \
515 return _str; \
516 }
517 ECN_STATE_TO_STRING(invalid, "Invalid")
518 ECN_STATE_TO_STRING(feature_disabled, "Disabled")
519 ECN_STATE_TO_STRING(feature_enabled, "Enabled")
520 ECN_STATE_TO_STRING(negotiation_blackholed, "Blackholed")
521 ECN_STATE_TO_STRING(ace_bleaching_detected, "ACE bleaching")
522 ECN_STATE_TO_STRING(negotiation_success, "Capable")
523 ECN_STATE_TO_STRING(negotiation_success_ect_mangling_detected, "ECT mangling")
524 ECN_STATE_TO_STRING(negotiation_success_ect_bleaching_detected, "ECT bleaching")
525 #undef ECN_STATE_TO_STRING
526 case tcp_connection_client_classic_ecn_available:
527 return "Classic ECN";
528 case tcp_connection_client_ecn_not_available:
529 return "Unavailable";
530 }
531 return "Unknown";
532 }
533
534 static const char *
tcp_connection_server_accurate_ecn_state_to_string(tcp_connection_server_accurate_ecn_state_t state)535 tcp_connection_server_accurate_ecn_state_to_string(tcp_connection_server_accurate_ecn_state_t state)
536 {
537 switch (state) {
538 #define ECN_STATE_TO_STRING(_s, _str) \
539 case tcp_connection_server_accurate_ecn_##_s: { \
540 return _str; \
541 }
542 ECN_STATE_TO_STRING(invalid, "Invalid")
543 ECN_STATE_TO_STRING(feature_disabled, "Disabled")
544 ECN_STATE_TO_STRING(feature_enabled, "Enabled")
545 ECN_STATE_TO_STRING(requested, "Requested")
546 ECN_STATE_TO_STRING(negotiation_blackholed, "Blackholed")
547 ECN_STATE_TO_STRING(ace_bleaching_detected, "ACE bleaching")
548 ECN_STATE_TO_STRING(negotiation_success, "Capable")
549 ECN_STATE_TO_STRING(negotiation_success_ect_mangling_detected, "ECT mangling")
550 ECN_STATE_TO_STRING(negotiation_success_ect_bleaching_detected, "ECT bleaching")
551 #undef ECN_STATE_TO_STRING
552 case tcp_connection_server_no_ecn_requested:
553 return "Not requested";
554 case tcp_connection_server_classic_ecn_requested:
555 return "Classic ECN requested";
556 }
557 return "Unknown";
558 }
559
560 __attribute__((noinline))
561 void
tcp_log_connection_summary(struct tcpcb * tp)562 tcp_log_connection_summary(struct tcpcb *tp)
563 {
564 struct inpcb *inp;
565 struct socket *so;
566 struct ifnet *ifp;
567 uint32_t conntime = 0;
568 uint32_t duration = 0;
569 char laddr_buf[ADDRESS_STR_LEN];
570 char faddr_buf[ADDRESS_STR_LEN];
571 in_port_t local_port;
572 in_port_t foreign_port;
573
574 if (tp == NULL || tp->t_inpcb == NULL || tp->t_inpcb->inp_socket == NULL) {
575 return;
576 }
577
578 /* Do not log too much */
579 if (tcp_log_is_rate_limited()) {
580 return;
581 }
582 inp = tp->t_inpcb;
583 so = inp->inp_socket;
584
585 local_port = inp->inp_lport;
586 foreign_port = inp->inp_fport;
587
588 /* Make sure the summary is logged once */
589 if (inp->inp_flags2 & INP2_LOGGED_SUMMARY) {
590 return;
591 }
592 inp->inp_flags2 |= INP2_LOGGED_SUMMARY;
593
594 /*
595 * t_connect_time is the time when the connection started on
596 * the first SYN.
597 *
598 * t_starttime is when the three way handshake was completed.
599 */
600 if (tp->t_connect_time > 0) {
601 duration = tcp_now - tp->t_connect_time;
602
603 if (tp->t_starttime > 0) {
604 conntime = tp->t_starttime - tp->t_connect_time;
605 }
606 }
607
608 ifp = inp->inp_last_outifp != NULL ? inp->inp_last_outifp :
609 inp->inp_boundifp != NULL ? inp->inp_boundifp : NULL;
610
611 tcp_log_inp_addresses(inp, laddr_buf, sizeof(laddr_buf), faddr_buf, sizeof(faddr_buf));
612
613 /*
614 * Need to use 2 log messages because the size of the summary
615 */
616
617 #define TCP_LOG_CONNECTION_SUMMARY_FMT \
618 "tcp_connection_summary " \
619 TCP_LOG_COMMON_PCB_FMT \
620 "Duration: %u.%u sec " \
621 "Conn_Time: %u.%u sec " \
622 "bytes in/out: %llu/%llu " \
623 "pkts in/out: %llu/%llu " \
624 "pkt rxmit: %u " \
625 "ooo pkts: %u dup bytes in: %u ACKs delayed: %u delayed ACKs sent: %u\n" \
626 "rtt: %u.%03u ms " \
627 "rttvar: %u.%03u ms " \
628 "base rtt: %u ms " \
629 "so_error: %d " \
630 "svc/tc: %u"
631
632 #define TCP_LOG_CONNECTION_SUMMARY_ARGS \
633 TCP_LOG_COMMON_PCB_ARGS, \
634 duration / TCP_RETRANSHZ, duration % TCP_RETRANSHZ, \
635 conntime / TCP_RETRANSHZ, conntime % TCP_RETRANSHZ, \
636 inp->inp_stat->rxbytes, inp->inp_stat->txbytes, \
637 inp->inp_stat->rxpackets, inp->inp_stat->txpackets, \
638 tp->t_stat.rxmitpkts, \
639 tp->t_rcvoopack, tp->t_stat.rxduplicatebytes, tp->t_stat.acks_delayed, tp->t_stat.delayed_acks_sent, \
640 P_MS(tp->t_srtt, TCP_RTT_SHIFT), \
641 P_MS(tp->t_rttvar, TCP_RTTVAR_SHIFT), \
642 get_base_rtt(tp), \
643 so->so_error, \
644 (so->so_flags1 & SOF1_TC_NET_SERV_TYPE) ? so->so_netsvctype : so->so_traffic_class
645
646 os_log(OS_LOG_DEFAULT, TCP_LOG_CONNECTION_SUMMARY_FMT,
647 TCP_LOG_CONNECTION_SUMMARY_ARGS);
648 #undef TCP_LOG_CONNECTION_SUMMARY_FMT
649 #undef TCP_LOG_CONNECTION_SUMMARY_ARGS
650
651 #define TCP_LOG_CONNECTION_SUMMARY_FMT \
652 "tcp_connection_summary " \
653 TCP_LOG_COMMON_PCB_FMT \
654 "flowctl: %llu suspnd: %llu " \
655 "SYN in/out: %u/%u " \
656 "FIN in/out: %u/%u " \
657 "RST in/out: %u/%u " \
658 "AccECN (client/server): %s/%s\n" \
659
660 #define TCP_LOG_CONNECTION_SUMMARY_ARGS \
661 TCP_LOG_COMMON_PCB_ARGS, \
662 inp->inp_fadv_flow_ctrl_cnt, inp->inp_fadv_suspended_cnt, \
663 tp->t_syn_rcvd, tp->t_syn_sent, \
664 tp->t_fin_rcvd, tp->t_fin_sent, \
665 tp->t_rst_rcvd, tp->t_rst_sent, \
666 tcp_connection_client_accurate_ecn_state_to_string(tp->t_client_accecn_state), \
667 tcp_connection_server_accurate_ecn_state_to_string(tp->t_server_accecn_state)
668
669 os_log(OS_LOG_DEFAULT, TCP_LOG_CONNECTION_SUMMARY_FMT,
670 TCP_LOG_CONNECTION_SUMMARY_ARGS);
671 #undef TCP_LOG_CONNECTION_SUMMARY_FMT
672 #undef TCP_LOG_CONNECTION_SUMMARY_ARGS
673 }
674
675 __attribute__((noinline))
676 static bool
tcp_log_pkt_addresses(void * hdr,struct tcphdr * th,bool outgoing,char * lbuf,socklen_t lbuflen,char * fbuf,socklen_t fbuflen)677 tcp_log_pkt_addresses(void *hdr, struct tcphdr *th, bool outgoing,
678 char *lbuf, socklen_t lbuflen, char *fbuf, socklen_t fbuflen)
679 {
680 bool isipv6;
681 uint8_t thflags;
682
683 isipv6 = (((struct ip *)hdr)->ip_v == 6);
684 thflags = th->th_flags;
685
686 if (isipv6) {
687 struct ip6_hdr *ip6 = (struct ip6_hdr *)hdr;
688
689 if (memcmp(&ip6->ip6_src, &in6addr_loopback, sizeof(struct in6_addr)) == 0 ||
690 memcmp(&ip6->ip6_dst, &in6addr_loopback, sizeof(struct in6_addr)) == 0) {
691 if (!(tcp_log_enable_flags & TLEF_DST_LOOPBACK)) {
692 return false;
693 }
694 }
695
696 if (inp_log_privacy != 0) {
697 strlcpy(lbuf, "<IPv6-redacted>", lbuflen);
698 strlcpy(fbuf, "<IPv6-redacted>", fbuflen);
699 } else if (outgoing) {
700 inet_ntop(AF_INET6, &ip6->ip6_src, lbuf, lbuflen);
701 inet_ntop(AF_INET6, &ip6->ip6_dst, fbuf, fbuflen);
702 } else {
703 inet_ntop(AF_INET6, &ip6->ip6_dst, lbuf, lbuflen);
704 inet_ntop(AF_INET6, &ip6->ip6_src, fbuf, fbuflen);
705 }
706 } else {
707 struct ip *ip = (struct ip *)hdr;
708
709 if (ntohl(ip->ip_src.s_addr) == INADDR_LOOPBACK ||
710 ntohl(ip->ip_dst.s_addr) == INADDR_LOOPBACK) {
711 if (!(tcp_log_enable_flags & TLEF_DST_LOOPBACK)) {
712 return false;
713 }
714 }
715
716 if (inp_log_privacy != 0) {
717 strlcpy(lbuf, "<IPv4-redacted>", lbuflen);
718 strlcpy(fbuf, "<IPv4-redacted>", fbuflen);
719 } else if (outgoing) {
720 inet_ntop(AF_INET, (void *)&ip->ip_src.s_addr, lbuf, lbuflen);
721 inet_ntop(AF_INET, (void *)&ip->ip_dst.s_addr, fbuf, fbuflen);
722 } else {
723 inet_ntop(AF_INET, (void *)&ip->ip_dst.s_addr, lbuf, lbuflen);
724 inet_ntop(AF_INET, (void *)&ip->ip_src.s_addr, fbuf, fbuflen);
725 }
726 }
727 return true;
728 }
729
730 /*
731 * Note: currently only used in the input path
732 */
733 __attribute__((noinline))
734 void
tcp_log_drop_pcb(void * hdr,struct tcphdr * th,struct tcpcb * tp,bool outgoing,const char * reason)735 tcp_log_drop_pcb(void *hdr, struct tcphdr *th, struct tcpcb *tp, bool outgoing, const char *reason)
736 {
737 struct inpcb *inp;
738 struct socket *so;
739 struct ifnet *ifp;
740 char laddr_buf[ADDRESS_STR_LEN];
741 char faddr_buf[ADDRESS_STR_LEN];
742 in_port_t local_port;
743 in_port_t foreign_port;
744 const char *direction = "";
745
746 if (tp == NULL) {
747 return;
748 }
749 inp = tp->t_inpcb;
750 if (inp == NULL) {
751 return;
752 }
753 so = inp->inp_socket;
754 if (so == NULL) {
755 return;
756 }
757
758 /* Do not log common drops after the connection termination is logged */
759 if ((inp->inp_flags2 & INP2_LOGGED_SUMMARY) && ((so->so_state & SS_NOFDREF) ||
760 (so->so_flags & SOF_DEFUNCT) || (so->so_state & SS_CANTRCVMORE))) {
761 return;
762 }
763
764 /* Do not log too much */
765 if (tcp_log_is_rate_limited()) {
766 return;
767 }
768
769 /* Use the packet addresses when in the data path */
770 if (hdr != NULL && th != NULL) {
771 if (outgoing) {
772 local_port = th->th_sport;
773 foreign_port = th->th_dport;
774 direction = "outgoing ";
775 } else {
776 local_port = th->th_dport;
777 foreign_port = th->th_sport;
778 direction = "incoming ";
779 }
780 (void) tcp_log_pkt_addresses(hdr, th, outgoing, laddr_buf, sizeof(laddr_buf), faddr_buf, sizeof(faddr_buf));
781 } else {
782 local_port = inp->inp_lport;
783 foreign_port = inp->inp_fport;
784 tcp_log_inp_addresses(inp, laddr_buf, sizeof(laddr_buf), faddr_buf, sizeof(faddr_buf));
785 }
786
787 ifp = inp->inp_last_outifp != NULL ? inp->inp_last_outifp :
788 inp->inp_boundifp != NULL ? inp->inp_boundifp : NULL;
789
790 #define TCP_LOG_DROP_PCB_FMT \
791 "tcp drop %s" \
792 TCP_LOG_COMMON_PCB_FMT \
793 "t_state: %s " \
794 "so_error: %d " \
795 "reason: %s"
796
797 #define TCP_LOG_DROP_PCB_ARGS \
798 direction, \
799 TCP_LOG_COMMON_PCB_ARGS, \
800 tcpstates[tp->t_state], \
801 so->so_error, \
802 reason
803
804 os_log(OS_LOG_DEFAULT, TCP_LOG_DROP_PCB_FMT,
805 TCP_LOG_DROP_PCB_ARGS);
806 #undef TCP_LOG_DROP_PCB_FMT
807 #undef TCP_LOG_DROP_PCB_ARGS
808 }
809
810 #define TCP_LOG_TH_FLAGS_COMMON_FMT \
811 "tcp control %s " \
812 "%s" \
813 "%s" \
814 "%s" \
815 "%s" \
816 TCP_LOG_COMMON_FMT
817
818 #define TCP_LOG_TH_FLAGS_COMMON_ARGS \
819 outgoing ? "outgoing" : "incoming", \
820 thflags & TH_SYN ? "SYN " : "", \
821 thflags & TH_FIN ? "FIN " : "", \
822 thflags & TH_RST ? "RST " : "", \
823 thflags & TH_ACK ? "ACK " : "", \
824 TCP_LOG_COMMON_ARGS
825
826 static bool
should_log_th_flags(uint8_t thflags,struct tcpcb * tp,bool outgoing,struct ifnet * ifp)827 should_log_th_flags(uint8_t thflags, struct tcpcb *tp, bool outgoing, struct ifnet *ifp)
828 {
829 /*
830 * Check logging is enabled for interface for TCP control packets
831 *
832 * Note: the type of tcp_log_thflags_if_family is uint64_t but we
833 * access its value as bit string so we have to pay extra care to avoid
834 * out of bound access
835 */
836 if (ifp != NULL && (ifp->if_family >= (sizeof(tcp_log_thflags_if_family) << 3) ||
837 !bitstr_test((bitstr_t *)&tcp_log_thflags_if_family, ifp->if_family))) {
838 return false;
839 }
840 /*
841 * Log when seeing 3 SYN retransmissions of more on a TCP PCB
842 */
843 if (tp != NULL &&
844 ((thflags & TH_SYN) && (tcp_log_enable_flags & TLEF_SYN_RXMT) &&
845 ((outgoing && tp->t_syn_sent > 3) || (!outgoing && tp->t_syn_rcvd > 3)))) {
846 return true;
847 }
848 /*
849 * Log control packet when enabled
850 */
851 if ((((thflags & TH_SYN) && (tcp_log_enable_flags & TLEF_THF_SYN)) ||
852 ((thflags & TH_FIN) && (tcp_log_enable_flags & TLEF_THF_FIN)) ||
853 ((thflags & TH_RST) && (tcp_log_enable_flags & TLEF_THF_RST)))) {
854 return true;
855 }
856 return false;
857 }
858
859 __attribute__((noinline))
860 void
tcp_log_th_flags(void * hdr,struct tcphdr * th,struct tcpcb * tp,bool outgoing,struct ifnet * ifp)861 tcp_log_th_flags(void *hdr, struct tcphdr *th, struct tcpcb *tp, bool outgoing, struct ifnet *ifp)
862 {
863 struct inpcb *inp = tp->t_inpcb;
864 struct socket *so = inp != NULL ? inp->inp_socket : NULL;
865 char laddr_buf[ADDRESS_STR_LEN];
866 char faddr_buf[ADDRESS_STR_LEN];
867 in_port_t local_port;
868 in_port_t foreign_port;
869 uint8_t thflags;
870
871 if (hdr == NULL || th == NULL) {
872 return;
873 }
874
875 thflags = th->th_flags;
876
877 if (should_log_th_flags(thflags, tp, outgoing, ifp) == false) {
878 return;
879 }
880
881 if (outgoing) {
882 local_port = th->th_sport;
883 foreign_port = th->th_dport;
884 } else {
885 local_port = th->th_dport;
886 foreign_port = th->th_sport;
887 }
888 if (!tcp_log_pkt_addresses(hdr, th, outgoing, laddr_buf, sizeof(laddr_buf), faddr_buf, sizeof(faddr_buf))) {
889 return;
890 }
891
892 /* Do not log too much */
893 if (tcp_log_is_rate_limited()) {
894 return;
895 }
896
897 /*
898 * When no PCB or socket just log the packet
899 */
900 if (tp == NULL || so == NULL || inp == NULL) {
901 #define TCP_LOG_TH_FLAGS_NO_PCB_FMT \
902 TCP_LOG_TH_FLAGS_COMMON_FMT \
903 TCP_LOG_COMMON_FMT
904 #define TCP_LOG_TH_FLAGS_NO_PCB_ARGS \
905 TCP_LOG_TH_FLAGS_COMMON_ARGS, \
906 TCP_LOG_COMMON_ARGS
907
908 os_log(OS_LOG_DEFAULT, TCP_LOG_TH_FLAGS_NO_PCB_FMT,
909 TCP_LOG_TH_FLAGS_NO_PCB_ARGS);
910 #undef TCP_LOG_TH_FLAGS_NO_PCB_FMT
911 #undef TCP_LOG_TH_FLAGS_NO_PCB_ARGS
912 } else {
913 #define TCP_LOG_TH_FLAGS_PCB_FMT \
914 TCP_LOG_TH_FLAGS_COMMON_FMT \
915 TCP_LOG_COMMON_PCB_FMT \
916 "SYN in/out: %u/%u "
917
918 #define TCP_LOG_TH_FLAGS_PCB_ARGS \
919 TCP_LOG_TH_FLAGS_COMMON_ARGS, \
920 TCP_LOG_COMMON_PCB_ARGS, \
921 tp->t_syn_rcvd, tp->t_syn_sent
922
923 os_log(OS_LOG_DEFAULT, TCP_LOG_TH_FLAGS_PCB_FMT,
924 TCP_LOG_TH_FLAGS_PCB_ARGS);
925 #undef TCP_LOG_TH_FLAGS_PCB_FMT
926 #undef TCP_LOG_TH_FLAGS_PCB_ARGS
927 }
928 }
929
930 __attribute__((noinline))
931 void
tcp_log_drop_pkt(void * hdr,struct tcphdr * th,struct ifnet * ifp,const char * reason)932 tcp_log_drop_pkt(void *hdr, struct tcphdr *th, struct ifnet *ifp, const char *reason)
933 {
934 char laddr_buf[ADDRESS_STR_LEN];
935 char faddr_buf[ADDRESS_STR_LEN];
936 in_port_t local_port;
937 in_port_t foreign_port;
938 uint8_t thflags;
939 bool outgoing = false; /* This is only for incoming packets */
940
941 if (hdr == NULL || th == NULL) {
942 return;
943 }
944
945 local_port = th->th_dport;
946 foreign_port = th->th_sport;
947 thflags = th->th_flags;
948
949 if (should_log_th_flags(thflags, NULL, outgoing, ifp) == false) {
950 return;
951 }
952
953 if (!tcp_log_pkt_addresses(hdr, th, outgoing, laddr_buf, sizeof(laddr_buf), faddr_buf, sizeof(faddr_buf))) {
954 return;
955 }
956
957 /* Do not log too much */
958 if (tcp_log_is_rate_limited()) {
959 return;
960 }
961
962 #define TCP_LOG_DROP_PKT_FMT \
963 "tcp drop incoming control packet " \
964 TCP_LOG_TH_FLAGS_COMMON_FMT \
965 "reason: %s"
966
967 #define TCP_LOG_DROP_PKT_ARGS \
968 TCP_LOG_TH_FLAGS_COMMON_ARGS, \
969 reason != NULL ? reason : ""
970
971 os_log(OS_LOG_DEFAULT, TCP_LOG_DROP_PKT_FMT,
972 TCP_LOG_DROP_PKT_ARGS);
973 #undef TCP_LOG_DROP_PKT_FMT
974 #undef TCP_LOG_DROP_PKT_ARGS
975 }
976
977 __attribute__((noinline))
978 void
tcp_log_message(const char * func_name,int line_no,struct tcpcb * tp,const char * format,...)979 tcp_log_message(const char *func_name, int line_no, struct tcpcb *tp, const char *format, ...)
980 {
981 struct inpcb *inp;
982 struct socket *so;
983 struct ifnet *ifp;
984 char laddr_buf[ADDRESS_STR_LEN];
985 char faddr_buf[ADDRESS_STR_LEN];
986 in_port_t local_port;
987 in_port_t foreign_port;
988 char message[256];
989
990 if (tp == NULL || tp->t_inpcb == NULL || tp->t_inpcb->inp_socket == NULL) {
991 return;
992 }
993
994 /* Do not log too much */
995 if (tcp_log_is_rate_limited()) {
996 return;
997 }
998 inp = tp->t_inpcb;
999 so = inp->inp_socket;
1000
1001 local_port = inp->inp_lport;
1002 foreign_port = inp->inp_fport;
1003
1004 ifp = inp->inp_last_outifp != NULL ? inp->inp_last_outifp :
1005 inp->inp_boundifp != NULL ? inp->inp_boundifp : NULL;
1006
1007 tcp_log_inp_addresses(inp, laddr_buf, sizeof(laddr_buf), faddr_buf, sizeof(faddr_buf));
1008
1009 va_list ap;
1010 va_start(ap, format);
1011 vsnprintf(message, sizeof(message), format, ap);
1012 va_end(ap);
1013
1014 #define TCP_LOG_MESSAGE_FMT \
1015 "tcp (%s:%d) " \
1016 TCP_LOG_COMMON_PCB_FMT \
1017 "bytes in/out: %llu/%llu " \
1018 "pkts in/out: %llu/%llu " \
1019 "%s"
1020
1021 #define TCP_LOG_MESSAGE_ARGS \
1022 func_name, line_no, \
1023 TCP_LOG_COMMON_PCB_ARGS, \
1024 inp->inp_stat->rxbytes, inp->inp_stat->txbytes, \
1025 inp->inp_stat->rxpackets, inp->inp_stat->txpackets, \
1026 message
1027
1028 os_log(OS_LOG_DEFAULT, TCP_LOG_MESSAGE_FMT,
1029 TCP_LOG_MESSAGE_ARGS);
1030 #undef TCP_LOG_MESSAGE_FMT
1031 #undef TCP_LOG_MESSAGE_ARGS
1032 }
1033
1034 #if SKYWALK
1035 __attribute__((noinline))
1036 void
tcp_log_fsw_flow(const char * func_name,int line_no,struct tcpcb * tp,const char * format,...)1037 tcp_log_fsw_flow(const char *func_name, int line_no, struct tcpcb *tp, const char *format, ...)
1038 {
1039 struct inpcb *inp;
1040 struct socket *so;
1041 struct ifnet *ifp;
1042 char laddr_buf[ADDRESS_STR_LEN];
1043 char faddr_buf[ADDRESS_STR_LEN];
1044 in_port_t local_port;
1045 in_port_t foreign_port;
1046 uuid_string_t flow_uuid_str;
1047 char message[256];
1048
1049 if (tp == NULL || tp->t_inpcb == NULL || tp->t_inpcb->inp_socket == NULL) {
1050 return;
1051 }
1052
1053 /* Do not log too much */
1054 if (tcp_log_is_rate_limited()) {
1055 return;
1056 }
1057 inp = tp->t_inpcb;
1058 so = inp->inp_socket;
1059
1060 local_port = inp->inp_lport;
1061 foreign_port = inp->inp_fport;
1062
1063 ifp = inp->inp_last_outifp != NULL ? inp->inp_last_outifp :
1064 inp->inp_boundifp != NULL ? inp->inp_boundifp : NULL;
1065
1066 tcp_log_inp_addresses(inp, laddr_buf, sizeof(laddr_buf), faddr_buf, sizeof(faddr_buf));
1067
1068 uuid_unparse_upper(tp->t_flow_uuid, flow_uuid_str);
1069
1070 va_list ap;
1071 va_start(ap, format);
1072 vsnprintf(message, sizeof(message), format, ap);
1073 va_end(ap);
1074
1075 #define TCP_LOG_FSW_FLOW_MESSAGE_FMT \
1076 "tcp (%s:%d) " \
1077 TCP_LOG_COMMON_PCB_FMT \
1078 "flow %s %s"
1079
1080 #define TCP_LOG_FSW_FLOW_MESSAGE_ARGS \
1081 func_name, line_no, \
1082 TCP_LOG_COMMON_PCB_ARGS, \
1083 flow_uuid_str, \
1084 message
1085
1086 os_log(OS_LOG_DEFAULT, TCP_LOG_FSW_FLOW_MESSAGE_FMT,
1087 TCP_LOG_FSW_FLOW_MESSAGE_ARGS);
1088 #undef TCP_LOG_FSW_FLOW_MESSAGE_FMT
1089 #undef TCP_LOG_FSW_FLOW_MESSAGE_ARGS
1090 }
1091 #endif /* SKYWALK */
1092
1093 void
tcp_log_state_change(struct tcpcb * tp,int new_state)1094 tcp_log_state_change(struct tcpcb *tp, int new_state)
1095 {
1096 struct inpcb *inp;
1097 struct socket *so;
1098 struct ifnet *ifp;
1099 uint32_t conntime = 0;
1100 uint32_t duration = 0;
1101 char laddr_buf[ADDRESS_STR_LEN];
1102 char faddr_buf[ADDRESS_STR_LEN];
1103 in_port_t local_port;
1104 in_port_t foreign_port;
1105
1106 if (tp == NULL || tp->t_inpcb == NULL || tp->t_inpcb->inp_socket == NULL) {
1107 return;
1108 }
1109 if (new_state == tp->t_state) {
1110 return;
1111 }
1112
1113 /* Do not log too much */
1114 if (tcp_log_is_rate_limited()) {
1115 return;
1116 }
1117
1118 inp = tp->t_inpcb;
1119 so = inp->inp_socket;
1120
1121 local_port = inp->inp_lport;
1122 foreign_port = inp->inp_fport;
1123
1124 /*
1125 * t_connect_time is the time when the connection started on
1126 * the first SYN.
1127 *
1128 * t_starttime is when the three way handshake was completed.
1129 */
1130 if (tp->t_connect_time > 0) {
1131 duration = tcp_now - tp->t_connect_time;
1132
1133 if (tp->t_starttime > 0) {
1134 conntime = tp->t_starttime - tp->t_connect_time;
1135 }
1136 }
1137
1138 ifp = inp->inp_last_outifp != NULL ? inp->inp_last_outifp :
1139 inp->inp_boundifp != NULL ? inp->inp_boundifp : NULL;
1140
1141 tcp_log_inp_addresses(inp, laddr_buf, sizeof(laddr_buf), faddr_buf, sizeof(faddr_buf));
1142
1143 #define TCP_LOG_STATE_FMT \
1144 "tcp_state_changed " \
1145 TCP_LOG_COMMON_PCB_FMT
1146
1147 #define TCP_LOG_STATE_ARGS \
1148 TCP_LOG_COMMON_ARGS, \
1149 so != NULL ? so->so_gencnt : 0, \
1150 tcpstates[new_state], \
1151 inp->inp_last_proc_name, so->last_pid
1152
1153 os_log(OS_LOG_DEFAULT, TCP_LOG_STATE_FMT,
1154 TCP_LOG_STATE_ARGS);
1155 #undef TCP_LOG_STATE_FMT
1156 #undef TCP_LOG_STATE_ARGS
1157 }
1158
1159 __attribute__((noinline))
1160 void
tcp_log_output(const char * func_name,int line_no,struct tcpcb * tp,const char * format,...)1161 tcp_log_output(const char *func_name, int line_no, struct tcpcb *tp, const char *format, ...)
1162 {
1163 struct inpcb *inp;
1164 struct socket *so;
1165 struct ifnet *ifp;
1166 char laddr_buf[ADDRESS_STR_LEN];
1167 char faddr_buf[ADDRESS_STR_LEN];
1168 in_port_t local_port;
1169 in_port_t foreign_port;
1170 char message[256];
1171
1172 if (tp == NULL || tp->t_inpcb == NULL || tp->t_inpcb->inp_socket == NULL) {
1173 return;
1174 }
1175 /* Log only when fron send() or connect() */
1176 if ((tp->t_flagsext & TF_USR_OUTPUT) == 0) {
1177 return;
1178 }
1179 /* Do not log too much */
1180 if (tcp_log_is_rate_limited()) {
1181 return;
1182 }
1183 inp = tp->t_inpcb;
1184 so = inp->inp_socket;
1185
1186 local_port = inp->inp_lport;
1187 foreign_port = inp->inp_fport;
1188
1189 ifp = inp->inp_last_outifp != NULL ? inp->inp_last_outifp :
1190 inp->inp_boundifp != NULL ? inp->inp_boundifp : NULL;
1191
1192 tcp_log_inp_addresses(inp, laddr_buf, sizeof(laddr_buf), faddr_buf, sizeof(faddr_buf));
1193
1194 va_list ap;
1195 va_start(ap, format);
1196 vsnprintf(message, sizeof(message), format, ap);
1197 va_end(ap);
1198
1199 #define TCP_LOG_MESSAGE_FMT \
1200 "tcp (%s:%d) " \
1201 TCP_LOG_COMMON_PCB_FMT \
1202 "bytes in/out: %llu/%llu " \
1203 "pkts in/out: %llu/%llu " \
1204 "rxmit pkts/bytes: %u/%u" \
1205 "%s"
1206
1207 #define TCP_LOG_MESSAGE_ARGS \
1208 func_name, line_no, \
1209 TCP_LOG_COMMON_PCB_ARGS, \
1210 inp->inp_stat->rxbytes, inp->inp_stat->txbytes, \
1211 inp->inp_stat->rxpackets, inp->inp_stat->txpackets, \
1212 tp->t_stat.rxmitpkts, tp->t_stat.txretransmitbytes, \
1213 message
1214
1215 os_log(OS_LOG_DEFAULT, TCP_LOG_MESSAGE_FMT,
1216 TCP_LOG_MESSAGE_ARGS);
1217 #undef TCP_LOG_MESSAGE_FMT
1218 #undef TCP_LOG_MESSAGE_ARGS
1219 }
1220