1 /*
2 * Copyright (c) 2018-2021 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 <netinet/ip.h>
35 #include <netinet/ip6.h>
36
37 #if !TCPDEBUG
38 #define TCPSTATES
39 #endif /* TCPDEBUG */
40 #include <netinet/tcp_fsm.h>
41
42 #include <netinet/tcp_log.h>
43
44 SYSCTL_NODE(_net_inet_tcp, OID_AUTO, log, CTLFLAG_RW | CTLFLAG_LOCKED, 0,
45 "TCP logs");
46
47 static int tcp_log_level_info = 0;
48 SYSCTL_INT(_net_inet_tcp_log, OID_AUTO, level_info,
49 CTLFLAG_RW | CTLFLAG_LOCKED, &tcp_log_level_info, 0, "");
50
51 #if (DEVELOPMENT || DEBUG)
52 #if defined(XNU_TARGET_OS_OSX)
53 /*
54 * Log less on macOS as sockets are more prevalent than channels
55 */
56 #define TCP_LOG_ENABLE_DEFAULT \
57 (TLEF_CONNECTION | TLEF_DST_LOCAL | TLEF_DST_GW | \
58 TLEF_DROP_NECP | TLEF_DROP_PCB)
59 #else /* XNU_TARGET_OS_OSX */
60 #define TCP_LOG_ENABLE_DEFAULT \
61 (TLEF_CONNECTION | TLEF_DST_LOCAL | TLEF_DST_GW | \
62 TLEF_DROP_NECP | TLEF_DROP_PCB | TLEF_DROP_PKT | TLEF_THF_SYN)
63 #endif /* XNU_TARGET_OS_OSX */
64 #else /* (DEVELOPMENT || DEBUG) */
65 #define TCP_LOG_ENABLE_DEFAULT 0
66 #endif /* (DEVELOPMENT || DEBUG) */
67
68 uint32_t tcp_log_enable_flags = TCP_LOG_ENABLE_DEFAULT;
69 SYSCTL_UINT(_net_inet_tcp_log, OID_AUTO, enable,
70 CTLFLAG_RW | CTLFLAG_LOCKED, &tcp_log_enable_flags, 0, "");
71
72 /*
73 * The following is a help to describe the values of the flags
74 */
75 #define X(name, value, description, ...) #description ":" #value " "
76 SYSCTL_STRING(_net_inet_tcp_log, OID_AUTO, enable_usage, CTLFLAG_RD | CTLFLAG_LOCKED,
77 TCP_ENABLE_FLAG_LIST, 0, "");
78 #undef X
79
80 /*
81 * Values for tcp_log_port when TLEF_RTT is enabled:
82 * 0: log all TCP connections regardless of the port numbers
83 * 1 to 65535: log TCP connections with this local or foreign port
84 * other: do not log (same effect as as tcp_log_rtt == 0)
85 */
86 uint32_t tcp_log_port = 0;
87 SYSCTL_UINT(_net_inet_tcp_log, OID_AUTO, rtt_port, CTLFLAG_RW | CTLFLAG_LOCKED,
88 &tcp_log_port, 0, "");
89
90 /*
91 * Values for tcp_log_thflags_if_family when TLEF_THF_XXX is enabled:
92 * 0: all interfaces
93 * other: only for interfaces with the corresponding interface functional type
94 */
95 #if (DEVELOPMENT || DEBUG)
96 #define TCP_LOG_THFLAGS_IF_FAMILY_DEFAULT IFNET_FAMILY_IPSEC
97 #else /* (DEVELOPMENT || DEBUG) */
98 #define TCP_LOG_THFLAGS_IF_FAMILY_DEFAULT 0
99 #endif /* (DEVELOPMENT || DEBUG) */
100
101 static uint32_t tcp_log_thflags_if_family = TCP_LOG_THFLAGS_IF_FAMILY_DEFAULT;
102 SYSCTL_UINT(_net_inet_tcp_log, OID_AUTO, thflags_if_family,
103 CTLFLAG_RW | CTLFLAG_LOCKED, &tcp_log_thflags_if_family, 0, "");
104
105 #if (DEVELOPMENT || DEBUG)
106 #define TCP_LOG_PRIVACY_DEFAULT 0
107 #else
108 #define TCP_LOG_PRIVACY_DEFAULT 1
109 #endif /* (DEVELOPMENT || DEBUG) */
110
111 int tcp_log_privacy = TCP_LOG_PRIVACY_DEFAULT;
112 SYSCTL_INT(_net_inet_tcp_log, OID_AUTO, privacy,
113 CTLFLAG_RW | CTLFLAG_LOCKED, &tcp_log_privacy, 0, "");
114
115 #define TCP_LOG_RATE_LIMIT 600
116 static unsigned int tcp_log_rate_limit = TCP_LOG_RATE_LIMIT;
117 SYSCTL_UINT(_net_inet_tcp_log, OID_AUTO, rate_limit,
118 CTLFLAG_RW | CTLFLAG_LOCKED, &tcp_log_rate_limit, 0, "");
119
120 /* 1 minute by default */
121 #define TCP_LOG_RATE_DURATION 60
122 static unsigned int tcp_log_rate_duration = TCP_LOG_RATE_DURATION;
123 SYSCTL_UINT(_net_inet_tcp_log, OID_AUTO, rate_duration,
124 CTLFLAG_RW | CTLFLAG_LOCKED, &tcp_log_rate_duration, 0, "");
125
126 static unsigned long tcp_log_rate_max = 0;
127 SYSCTL_ULONG(_net_inet_tcp_log, OID_AUTO, rate_max,
128 CTLFLAG_RD | CTLFLAG_LOCKED, &tcp_log_rate_max, "");
129
130 static unsigned long tcp_log_rate_exceeded_total = 0;
131 SYSCTL_ULONG(_net_inet_tcp_log, OID_AUTO, rate_exceeded_total,
132 CTLFLAG_RD | CTLFLAG_LOCKED, &tcp_log_rate_exceeded_total, "");
133
134 static unsigned long tcp_log_rate_current = 0;
135 SYSCTL_ULONG(_net_inet_tcp_log, OID_AUTO, rate_current,
136 CTLFLAG_RD | CTLFLAG_LOCKED, &tcp_log_rate_current, "");
137
138 static bool tcp_log_rate_exceeded_logged = false;
139
140 static uint64_t tcp_log_current_period = 0;
141
142 #define ADDRESS_STR_LEN (MAX_IPv6_STR_LEN + 6)
143
144 #define TCP_LOG_COMMON_FMT \
145 "[%s:%u<->%s:%u] " \
146 "interface: %s " \
147 "(skipped: %lu)\n"
148
149 #define TCP_LOG_COMMON_ARGS \
150 laddr_buf, ntohs(local_port), faddr_buf, ntohs(foreign_port), \
151 ifp != NULL ? if_name(ifp) : "", \
152 tcp_log_rate_exceeded_total
153
154 #define TCP_LOG_COMMON_PCB_FMT \
155 TCP_LOG_COMMON_FMT \
156 "t_state: %s " \
157 "process: %s:%u "
158
159 #define TCP_LOG_COMMON_PCB_ARGS \
160 TCP_LOG_COMMON_ARGS, \
161 tcpstates[tp->t_state], \
162 inp->inp_last_proc_name, so->last_pid
163
164 /*
165 * Returns true when above the rate limit
166 */
167 static bool
tcp_log_is_rate_limited(void)168 tcp_log_is_rate_limited(void)
169 {
170 uint64_t current_net_period = net_uptime();
171
172 /* When set to zero it means to reset to default */
173 if (tcp_log_rate_duration == 0) {
174 tcp_log_rate_duration = TCP_LOG_RATE_DURATION;
175 }
176 if (tcp_log_rate_limit == 0) {
177 tcp_log_rate_duration = TCP_LOG_RATE_LIMIT;
178 }
179
180 if (current_net_period > tcp_log_current_period + tcp_log_rate_duration) {
181 if (tcp_log_rate_current > tcp_log_rate_max) {
182 tcp_log_rate_max = tcp_log_rate_current;
183 }
184 tcp_log_current_period = current_net_period;
185 tcp_log_rate_current = 0;
186 tcp_log_rate_exceeded_logged = false;
187 }
188
189 tcp_log_rate_current += 1;
190
191 if (tcp_log_rate_current > (unsigned long) tcp_log_rate_limit) {
192 tcp_log_rate_exceeded_total += 1;
193 return true;
194 }
195
196 return false;
197 }
198
199 static void
tcp_log_inp_addresses(struct inpcb * inp,char * lbuf,socklen_t lbuflen,char * fbuf,socklen_t fbuflen)200 tcp_log_inp_addresses(struct inpcb *inp, char *lbuf, socklen_t lbuflen, char *fbuf, socklen_t fbuflen)
201 {
202 /*
203 * Ugly but %{private} does not work in the kernel version of os_log()
204 */
205 if (tcp_log_privacy != 0) {
206 if (inp->inp_vflag & INP_IPV6) {
207 strlcpy(lbuf, "<IPv6-redacted>", lbuflen);
208 strlcpy(fbuf, "<IPv6-redacted>", fbuflen);
209 } else {
210 strlcpy(lbuf, "<IPv4-redacted>", lbuflen);
211 strlcpy(fbuf, "<IPv4-redacted>", fbuflen);
212 }
213 } else if (inp->inp_vflag & INP_IPV6) {
214 inet_ntop(AF_INET6, (void *)&inp->in6p_laddr, lbuf, lbuflen);
215 inet_ntop(AF_INET6, (void *)&inp->in6p_faddr, fbuf, fbuflen);
216 } else {
217 inet_ntop(AF_INET, (void *)&inp->inp_laddr.s_addr, lbuf, lbuflen);
218 inet_ntop(AF_INET, (void *)&inp->inp_faddr.s_addr, fbuf, fbuflen);
219 }
220 }
221
222 __attribute__((noinline))
223 void
tcp_log_rtt_info(const char * func_name,int line_no,struct tcpcb * tp)224 tcp_log_rtt_info(const char *func_name, int line_no, struct tcpcb *tp)
225 {
226 struct inpcb *inp = tp->t_inpcb;
227 struct socket *so = inp->inp_socket;
228 struct ifnet *ifp;
229 char laddr_buf[ADDRESS_STR_LEN];
230 char faddr_buf[ADDRESS_STR_LEN];
231 in_port_t local_port = inp->inp_lport;
232 in_port_t foreign_port = inp->inp_fport;
233
234 /* Do not log too much */
235 if (tcp_log_is_rate_limited()) {
236 return;
237 }
238
239 ifp = inp->inp_last_outifp != NULL ? inp->inp_last_outifp :
240 inp->inp_boundifp != NULL ? inp->inp_boundifp : NULL;
241
242 tcp_log_inp_addresses(inp, laddr_buf, sizeof(laddr_buf), faddr_buf, sizeof(faddr_buf));
243
244 os_log(OS_LOG_DEFAULT,
245 "tcp_rtt_info (%s:%d) "
246 TCP_LOG_COMMON_PCB_FMT
247 "base_rtt: %u ms rttcur: %u ms srtt: %u ms rttvar: %u ms rttmin: %u ms rxtcur: %u rxtshift: %u",
248 func_name, line_no,
249 TCP_LOG_COMMON_PCB_ARGS, get_base_rtt(tp),
250 tp->t_rttcur, tp->t_srtt >> TCP_RTT_SHIFT,
251 tp->t_rttvar >> TCP_RTTVAR_SHIFT,
252 tp->t_rttmin, tp->t_rxtcur, tp->t_rxtshift);
253 }
254
255 __attribute__((noinline))
256 void
tcp_log_rt_rtt(const char * func_name,int line_no,struct tcpcb * tp,struct rtentry * rt)257 tcp_log_rt_rtt(const char *func_name, int line_no, struct tcpcb *tp,
258 struct rtentry *rt)
259 {
260 struct inpcb *inp = tp->t_inpcb;
261 struct socket *so = inp->inp_socket;
262 struct ifnet *ifp;
263 char laddr_buf[ADDRESS_STR_LEN];
264 char faddr_buf[ADDRESS_STR_LEN];
265 in_port_t local_port = inp->inp_lport;
266 in_port_t foreign_port = inp->inp_fport;
267
268 /* Do not log too much */
269 if (tcp_log_is_rate_limited()) {
270 return;
271 }
272
273 ifp = inp->inp_last_outifp != NULL ? inp->inp_last_outifp :
274 inp->inp_boundifp != NULL ? inp->inp_boundifp : NULL;
275
276 tcp_log_inp_addresses(inp, laddr_buf, sizeof(laddr_buf), faddr_buf, sizeof(faddr_buf));
277
278 /*
279 * Log RTT values in milliseconds
280 */
281 os_log(OS_LOG_DEFAULT,
282 "tcp_rt_rtt (%s:%d) "
283 TCP_LOG_COMMON_PCB_FMT
284 "rt_rmx: RTV_RTT: %d ms rtt: %u ms rttvar: %u ms",
285 func_name, line_no,
286 TCP_LOG_COMMON_PCB_ARGS,
287 (rt->rt_rmx.rmx_locks & RTV_RTT),
288 rt->rt_rmx.rmx_rtt / (RTM_RTTUNIT / TCP_RETRANSHZ),
289 rt->rt_rmx.rmx_rttvar / (RTM_RTTUNIT / TCP_RETRANSHZ));
290 }
291
292 __attribute__((noinline))
293 void
tcp_log_rtt_change(const char * func_name,int line_no,struct tcpcb * tp,int old_srtt,int old_rttvar)294 tcp_log_rtt_change(const char *func_name, int line_no, struct tcpcb *tp,
295 int old_srtt, int old_rttvar)
296 {
297 int srtt_diff;
298 int rttvar_diff;
299
300 srtt_diff = ABS(tp->t_srtt - old_srtt) >> TCP_RTT_SHIFT;
301 rttvar_diff =
302 ABS((tp->t_rttvar - old_rttvar) >> TCP_RTTVAR_SHIFT);
303 if (srtt_diff >= 1000 || rttvar_diff >= 500) {
304 struct inpcb *inp = tp->t_inpcb;
305 struct socket *so = inp->inp_socket;
306 struct ifnet *ifp;
307 char laddr_buf[ADDRESS_STR_LEN];
308 char faddr_buf[ADDRESS_STR_LEN];
309 in_port_t local_port = inp->inp_lport;
310 in_port_t foreign_port = inp->inp_fport;
311
312 /* Do not log too much */
313 if (tcp_log_is_rate_limited()) {
314 return;
315 }
316
317 ifp = inp->inp_last_outifp != NULL ? inp->inp_last_outifp :
318 inp->inp_boundifp != NULL ? inp->inp_boundifp : NULL;
319
320 tcp_log_inp_addresses(inp, laddr_buf, sizeof(laddr_buf), faddr_buf, sizeof(faddr_buf));
321
322 os_log(OS_LOG_DEFAULT,
323 "tcp_rtt_change (%s:%d) "
324 TCP_LOG_COMMON_PCB_FMT
325 "srtt: %u ms old_rtt: %u ms "
326 "rttvar: %u old_rttvar: %u ms ",
327 func_name, line_no,
328 TCP_LOG_COMMON_PCB_ARGS,
329 tp->t_srtt >> TCP_RTT_SHIFT,
330 old_srtt >> TCP_RTT_SHIFT,
331 tp->t_rttvar >> TCP_RTTVAR_SHIFT,
332 old_rttvar >> TCP_RTTVAR_SHIFT);
333 }
334 }
335
336 __attribute__((noinline))
337 void
tcp_log_keepalive(const char * func_name,int line_no,struct tcpcb * tp,int32_t idle_time)338 tcp_log_keepalive(const char *func_name, int line_no, struct tcpcb *tp,
339 int32_t idle_time)
340 {
341 struct inpcb *inp = tp->t_inpcb;
342 struct socket *so = inp->inp_socket;
343 struct ifnet *ifp;
344 char laddr_buf[ADDRESS_STR_LEN];
345 char faddr_buf[ADDRESS_STR_LEN];
346 in_port_t local_port = inp->inp_lport;
347 in_port_t foreign_port = inp->inp_fport;
348
349 /* Do not log too much */
350 if (tcp_log_is_rate_limited()) {
351 return;
352 }
353
354 ifp = inp->inp_last_outifp != NULL ? inp->inp_last_outifp :
355 inp->inp_boundifp != NULL ? inp->inp_boundifp : NULL;
356
357 tcp_log_inp_addresses(inp, laddr_buf, sizeof(laddr_buf), faddr_buf, sizeof(faddr_buf));
358
359 os_log(OS_LOG_DEFAULT,
360 "tcp_keepalive (%s:%d) "
361 TCP_LOG_COMMON_PCB_FMT
362 "snd_una: %u snd_max: %u "
363 "SO_KA: %d RSTALL: %d TFOPRB: %d idle_time: %u "
364 "KIDLE: %d KINTV: %d KCNT: %d",
365 func_name, line_no,
366 TCP_LOG_COMMON_PCB_ARGS,
367 tp->snd_una, tp->snd_max,
368 tp->t_inpcb->inp_socket->so_options & SO_KEEPALIVE,
369 tp->t_flagsext & TF_DETECT_READSTALL,
370 tp->t_tfo_probe_state == TFO_PROBE_PROBING,
371 idle_time,
372 TCP_CONN_KEEPIDLE(tp), TCP_CONN_KEEPINTVL(tp),
373 TCP_CONN_KEEPCNT(tp));
374 }
375
376 #define P_MS(ms, shift) ((ms) >> (shift)), (((ms) * 1000) >> (shift)) % 1000
377
378 __attribute__((noinline))
379 void
tcp_log_connection(struct tcpcb * tp,const char * event,int error)380 tcp_log_connection(struct tcpcb *tp, const char *event, int error)
381 {
382 struct inpcb *inp;
383 struct socket *so;
384 struct ifnet *ifp;
385 char laddr_buf[ADDRESS_STR_LEN];
386 char faddr_buf[ADDRESS_STR_LEN];
387 in_port_t local_port;
388 in_port_t foreign_port;
389
390 if (tp == NULL || tp->t_inpcb == NULL || tp->t_inpcb->inp_socket == NULL || event == NULL) {
391 return;
392 }
393
394 /* Do not log too much */
395 if (tcp_log_is_rate_limited()) {
396 return;
397 }
398 inp = tp->t_inpcb;
399 so = inp->inp_socket;
400
401 local_port = inp->inp_lport;
402 foreign_port = inp->inp_fport;
403
404 ifp = inp->inp_last_outifp != NULL ? inp->inp_last_outifp :
405 inp->inp_boundifp != NULL ? inp->inp_boundifp : NULL;
406
407 tcp_log_inp_addresses(inp, laddr_buf, sizeof(laddr_buf), faddr_buf, sizeof(faddr_buf));
408
409 #define TCP_LOG_CONNECT_FMT \
410 "tcp %s: " \
411 TCP_LOG_COMMON_PCB_FMT \
412 "rtt: %u.%u ms " \
413 "rttvar: %u.%u ms " \
414 "base_rtt: %u ms " \
415 "error: %d " \
416 "so_error: %d " \
417 "svc/tc: %u"
418
419 #define TCP_LOG_CONNECT_ARGS \
420 event, \
421 TCP_LOG_COMMON_PCB_ARGS, \
422 P_MS(tp->t_srtt, TCP_RTT_SHIFT), \
423 P_MS(tp->t_rttvar, TCP_RTTVAR_SHIFT), \
424 get_base_rtt(tp), \
425 error, \
426 so->so_error, \
427 (so->so_flags1 & SOF1_TC_NET_SERV_TYPE) ? so->so_netsvctype : so->so_traffic_class
428
429 if (so->so_head == NULL) {
430 if (tcp_log_level_info == 0) {
431 os_log(OS_LOG_DEFAULT, TCP_LOG_CONNECT_FMT,
432 TCP_LOG_CONNECT_ARGS);
433 } else {
434 os_log_info(OS_LOG_DEFAULT, TCP_LOG_CONNECT_FMT,
435 TCP_LOG_CONNECT_ARGS);
436 }
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 if (tcp_log_level_info == 0) {
449 os_log(OS_LOG_DEFAULT, TCP_LOG_CONNECT_FMT "\n" TCP_LOG_CONN_Q_FMT,
450 TCP_LOG_CONNECT_ARGS, TCP_LOG_CONN_Q_ARGS);
451 } else {
452 os_log_info(OS_LOG_DEFAULT, TCP_LOG_CONNECT_FMT "\n" TCP_LOG_CONN_Q_FMT,
453 TCP_LOG_CONNECT_ARGS, TCP_LOG_CONN_Q_ARGS);
454 }
455 #undef TCP_LOG_CONN_Q_FMT
456 #undef TCP_LOG_CONN_Q_ARGS
457 }
458 #undef TCP_LOG_CONNECT_FMT
459 #undef TCP_LOG_CONNECT_ARGS
460 }
461
462 __attribute__((noinline))
463 void
tcp_log_listen(struct tcpcb * tp,int error)464 tcp_log_listen(struct tcpcb *tp, int error)
465 {
466 struct inpcb *inp = tp->t_inpcb;
467 struct socket *so = inp->inp_socket;
468 struct ifnet *ifp;
469 char laddr_buf[ADDRESS_STR_LEN];
470 char faddr_buf[ADDRESS_STR_LEN];
471 in_port_t local_port;
472 in_port_t foreign_port;
473
474 if (tp == NULL || tp->t_inpcb == NULL || tp->t_inpcb->inp_socket == NULL) {
475 return;
476 }
477
478 /* Do not log too much */
479 if (tcp_log_is_rate_limited()) {
480 return;
481 }
482 inp = tp->t_inpcb;
483 so = inp->inp_socket;
484
485 local_port = inp->inp_lport;
486 foreign_port = inp->inp_fport;
487
488 ifp = inp->inp_last_outifp != NULL ? inp->inp_last_outifp :
489 inp->inp_boundifp != NULL ? inp->inp_boundifp : NULL;
490
491 tcp_log_inp_addresses(inp, laddr_buf, sizeof(laddr_buf), faddr_buf, sizeof(faddr_buf));
492
493 #define TCP_LOG_LISTEN_FMT \
494 "tcp listen: " \
495 TCP_LOG_COMMON_PCB_FMT \
496 "so_qlimit: %d "\
497 "error: %d " \
498 "so_error: %d " \
499 "svc/tc: %u"
500
501 #define TCP_LOG_LISTEN_ARGS \
502 TCP_LOG_COMMON_PCB_ARGS, \
503 so->so_qlimit, \
504 error, \
505 so->so_error, \
506 (so->so_flags1 & SOF1_TC_NET_SERV_TYPE) ? so->so_netsvctype : so->so_traffic_class
507
508 if (tcp_log_level_info == 0) {
509 os_log(OS_LOG_DEFAULT, TCP_LOG_LISTEN_FMT,
510 TCP_LOG_LISTEN_ARGS);
511 } else {
512 os_log_info(OS_LOG_DEFAULT, TCP_LOG_LISTEN_FMT,
513 TCP_LOG_LISTEN_ARGS);
514 }
515 #undef TCP_LOG_LISTEN_FMT
516 #undef TCP_LOG_LISTEN_ARGS
517 }
518
519 __attribute__((noinline))
520 void
tcp_log_connection_summary(struct tcpcb * tp)521 tcp_log_connection_summary(struct tcpcb *tp)
522 {
523 struct inpcb *inp;
524 struct socket *so;
525 struct ifnet *ifp;
526 uint32_t conntime = 0;
527 uint32_t duration = 0;
528 char laddr_buf[ADDRESS_STR_LEN];
529 char faddr_buf[ADDRESS_STR_LEN];
530 in_port_t local_port;
531 in_port_t foreign_port;
532
533 if (tp == NULL || tp->t_inpcb == NULL || tp->t_inpcb->inp_socket == NULL) {
534 return;
535 }
536
537 /* Do not log too much */
538 if (tcp_log_is_rate_limited()) {
539 return;
540 }
541 inp = tp->t_inpcb;
542 so = inp->inp_socket;
543
544 local_port = inp->inp_lport;
545 foreign_port = inp->inp_fport;
546
547 /* Make sure the summary is logged once */
548 if (tp->t_flagsext & TF_LOGGED_CONN_SUMMARY) {
549 return;
550 }
551 tp->t_flagsext |= TF_LOGGED_CONN_SUMMARY;
552
553 /*
554 * t_connect_time is the time when the connection started on
555 * the first SYN.
556 *
557 * t_starttime is when the three way handshake was completed.
558 */
559 if (tp->t_connect_time > 0) {
560 duration = tcp_now - tp->t_connect_time;
561
562 if (tp->t_starttime > 0) {
563 conntime = tp->t_starttime - tp->t_connect_time;
564 }
565 }
566
567 ifp = inp->inp_last_outifp != NULL ? inp->inp_last_outifp :
568 inp->inp_boundifp != NULL ? inp->inp_boundifp : NULL;
569
570 tcp_log_inp_addresses(inp, laddr_buf, sizeof(laddr_buf), faddr_buf, sizeof(faddr_buf));
571
572 #define TCP_LOG_CONNECTION_SUMMARY_FMT \
573 "tcp_connection_summary " \
574 TCP_LOG_COMMON_PCB_FMT \
575 "Duration: %u.%u sec " \
576 "Conn_Time: %u.%u sec " \
577 "syn rxmit: %u\n" \
578 "bytes in/out: %llu/%llu " \
579 "pkts in/out: %llu/%llu " \
580 "rtt: %u.%03u ms " \
581 "rttvar: %u.%03u ms " \
582 "base rtt: %u ms " \
583 "pkt rxmit: %u " \
584 "ooo pkts: %u dup bytes in: %u ACKs delayed: %u delayed ACKs sent: %u " \
585 "so_error: %d " \
586 "svc/tc: %u"
587
588 #define TCP_LOG_CONNECTION_SUMMARY_ARGS \
589 TCP_LOG_COMMON_PCB_ARGS, \
590 duration / TCP_RETRANSHZ, duration % TCP_RETRANSHZ, \
591 conntime / TCP_RETRANSHZ, conntime % TCP_RETRANSHZ, \
592 tp->t_stat.synrxtshift, \
593 inp->inp_stat->rxbytes, inp->inp_stat->txbytes, \
594 inp->inp_stat->rxpackets, inp->inp_stat->txpackets, \
595 P_MS(tp->t_srtt, TCP_RTT_SHIFT), \
596 P_MS(tp->t_rttvar, TCP_RTTVAR_SHIFT), \
597 get_base_rtt(tp), \
598 tp->t_stat.rxmitpkts, \
599 tp->t_rcvoopack, tp->t_stat.rxduplicatebytes, tp->t_stat.acks_delayed, tp->t_stat.delayed_acks_sent, \
600 so->so_error, \
601 (so->so_flags1 & SOF1_TC_NET_SERV_TYPE) ? so->so_netsvctype : so->so_traffic_class
602
603 if (tcp_log_level_info == 0) {
604 os_log(OS_LOG_DEFAULT, TCP_LOG_CONNECTION_SUMMARY_FMT,
605 TCP_LOG_CONNECTION_SUMMARY_ARGS);
606 } else {
607 os_log_info(OS_LOG_DEFAULT, TCP_LOG_CONNECTION_SUMMARY_FMT,
608 TCP_LOG_CONNECTION_SUMMARY_ARGS);
609 }
610 #undef TCP_LOG_CONNECTION_SUMMARY_FMT
611 #undef TCP_LOG_CONNECTION_SUMMARY_ARGS
612 }
613
614 __attribute__((noinline))
615 static bool
tcp_log_pkt_addresses(void * hdr,struct tcphdr * th,bool outgoing,char * lbuf,socklen_t lbuflen,char * fbuf,socklen_t fbuflen)616 tcp_log_pkt_addresses(void *hdr, struct tcphdr *th, bool outgoing,
617 char *lbuf, socklen_t lbuflen, char *fbuf, socklen_t fbuflen)
618 {
619 bool isipv6;
620 uint8_t thflags;
621
622 isipv6 = (((struct ip *)hdr)->ip_v == 6);
623 thflags = th->th_flags;
624
625 if (isipv6) {
626 struct ip6_hdr *ip6 = (struct ip6_hdr *)hdr;
627
628 if (memcmp(&ip6->ip6_src, &in6addr_loopback, sizeof(struct in6_addr)) == 0 ||
629 memcmp(&ip6->ip6_dst, &in6addr_loopback, sizeof(struct in6_addr)) == 0) {
630 if (!(tcp_log_enable_flags & TLEF_DST_LOOPBACK)) {
631 return false;
632 }
633 }
634
635 if (tcp_log_privacy != 0) {
636 strlcpy(lbuf, "<IPv6-redacted>", lbuflen);
637 strlcpy(fbuf, "<IPv6-redacted>", fbuflen);
638 } else if (outgoing) {
639 inet_ntop(AF_INET6, &ip6->ip6_src, lbuf, lbuflen);
640 inet_ntop(AF_INET6, &ip6->ip6_dst, fbuf, fbuflen);
641 } else {
642 inet_ntop(AF_INET6, &ip6->ip6_dst, lbuf, lbuflen);
643 inet_ntop(AF_INET6, &ip6->ip6_src, fbuf, fbuflen);
644 }
645 } else {
646 struct ip *ip = (struct ip *)hdr;
647
648 if (ntohl(ip->ip_src.s_addr) == INADDR_LOOPBACK ||
649 ntohl(ip->ip_dst.s_addr) == INADDR_LOOPBACK) {
650 if (!(tcp_log_enable_flags & TLEF_DST_LOOPBACK)) {
651 return false;
652 }
653 }
654
655 if (tcp_log_privacy != 0) {
656 strlcpy(lbuf, "<IPv4-redacted>", lbuflen);
657 strlcpy(fbuf, "<IPv4-redacted>", fbuflen);
658 } else if (outgoing) {
659 inet_ntop(AF_INET, (void *)&ip->ip_src.s_addr, lbuf, lbuflen);
660 inet_ntop(AF_INET, (void *)&ip->ip_dst.s_addr, fbuf, fbuflen);
661 } else {
662 inet_ntop(AF_INET, (void *)&ip->ip_dst.s_addr, lbuf, lbuflen);
663 inet_ntop(AF_INET, (void *)&ip->ip_src.s_addr, fbuf, fbuflen);
664 }
665 }
666 return true;
667 }
668
669 /*
670 * Note: currently only used in the input path
671 */
672 __attribute__((noinline))
673 void
tcp_log_drop_pcb(void * hdr,struct tcphdr * th,struct tcpcb * tp,bool outgoing,const char * reason)674 tcp_log_drop_pcb(void *hdr, struct tcphdr *th, struct tcpcb *tp, bool outgoing, const char *reason)
675 {
676 struct inpcb *inp = tp->t_inpcb;
677 struct socket *so = inp->inp_socket;
678 struct ifnet *ifp;
679 char laddr_buf[ADDRESS_STR_LEN];
680 char faddr_buf[ADDRESS_STR_LEN];
681 in_port_t local_port;
682 in_port_t foreign_port;
683 const char *direction = "";
684
685 if (tp == NULL) {
686 return;
687 }
688
689 /* Do not log too much */
690 if (tcp_log_is_rate_limited()) {
691 return;
692 }
693
694 /* Use the packet addresses when in the data path */
695 if (hdr != NULL && th != NULL) {
696 if (outgoing) {
697 local_port = th->th_sport;
698 foreign_port = th->th_dport;
699 direction = "outgoing ";
700 } else {
701 local_port = th->th_dport;
702 foreign_port = th->th_sport;
703 direction = "incoming ";
704 }
705 (void) tcp_log_pkt_addresses(hdr, th, outgoing, laddr_buf, sizeof(laddr_buf), faddr_buf, sizeof(faddr_buf));
706 } else {
707 local_port = inp->inp_lport;
708 foreign_port = inp->inp_fport;
709 tcp_log_inp_addresses(inp, laddr_buf, sizeof(laddr_buf), faddr_buf, sizeof(faddr_buf));
710 }
711
712 ifp = inp->inp_last_outifp != NULL ? inp->inp_last_outifp :
713 inp->inp_boundifp != NULL ? inp->inp_boundifp : NULL;
714
715 #define TCP_LOG_DROP_PCB_FMT \
716 "tcp drop %s" \
717 TCP_LOG_COMMON_PCB_FMT \
718 "t_state: %s " \
719 "so_error: %d " \
720 "reason: %s"
721
722 #define TCP_LOG_DROP_PCB_ARGS \
723 direction, \
724 TCP_LOG_COMMON_PCB_ARGS, \
725 tcpstates[tp->t_state], \
726 so->so_error, \
727 reason
728
729 if (tcp_log_level_info == 0) {
730 os_log(OS_LOG_DEFAULT, TCP_LOG_DROP_PCB_FMT,
731 TCP_LOG_DROP_PCB_ARGS);
732 } else {
733 os_log_info(OS_LOG_DEFAULT, TCP_LOG_DROP_PCB_FMT,
734 TCP_LOG_DROP_PCB_ARGS);
735 }
736 #undef TCP_LOG_DROP_PCB_FMT
737 #undef TCP_LOG_DROP_PCB_ARGS
738 }
739
740 #define TCP_LOG_TH_FLAGS_COMMON_FMT \
741 "tcp control %s " \
742 "%s" \
743 "%s" \
744 "%s" \
745 "%s" \
746 TCP_LOG_COMMON_FMT
747
748 #define TCP_LOG_TH_FLAGS_COMMON_ARGS \
749 outgoing ? "outgoing" : "incoming", \
750 thflags & TH_SYN ? "SYN " : "", \
751 thflags & TH_FIN ? "FIN " : "", \
752 thflags & TH_RST ? "RST " : "", \
753 thflags & TH_ACK ? "ACK " : "", \
754 TCP_LOG_COMMON_ARGS
755
756 __attribute__((noinline))
757 void
tcp_log_th_flags(void * hdr,struct tcphdr * th,struct tcpcb * tp,bool outgoing,struct ifnet * ifp)758 tcp_log_th_flags(void *hdr, struct tcphdr *th, struct tcpcb *tp, bool outgoing, struct ifnet *ifp)
759 {
760 struct socket *so = tp->t_inpcb != NULL ? tp->t_inpcb->inp_socket : NULL;
761 char laddr_buf[ADDRESS_STR_LEN];
762 char faddr_buf[ADDRESS_STR_LEN];
763 in_port_t local_port;
764 in_port_t foreign_port;
765 uint8_t thflags;
766
767 if (hdr == NULL || th == NULL) {
768 return;
769 }
770
771 if (outgoing) {
772 local_port = th->th_sport;
773 foreign_port = th->th_dport;
774 } else {
775 local_port = th->th_dport;
776 foreign_port = th->th_sport;
777 }
778 thflags = th->th_flags;
779
780 if ((((thflags & TH_SYN) && (tcp_log_enable_flags & TLEF_THF_SYN)) ||
781 ((thflags & TH_FIN) && (tcp_log_enable_flags & TLEF_THF_FIN)) ||
782 ((thflags & TH_RST) && (tcp_log_enable_flags & TLEF_THF_RST))) == false) {
783 return;
784 }
785
786 if (ifp != NULL && tcp_log_thflags_if_family != 0 && ifp->if_family != tcp_log_thflags_if_family) {
787 return;
788 }
789
790 if (!tcp_log_pkt_addresses(hdr, th, outgoing, laddr_buf, sizeof(laddr_buf), faddr_buf, sizeof(faddr_buf))) {
791 return;
792 }
793
794 /* Do not log too much */
795 if (tcp_log_is_rate_limited()) {
796 return;
797 }
798
799 /*
800 * When no PCB or socket just log the packet
801 */
802 if (tp == NULL || so == NULL) {
803 if (tcp_log_level_info == 0) {
804 os_log(OS_LOG_DEFAULT, TCP_LOG_TH_FLAGS_COMMON_FMT " no pcb",
805 TCP_LOG_TH_FLAGS_COMMON_ARGS);
806 } else {
807 os_log_info(OS_LOG_DEFAULT, TCP_LOG_TH_FLAGS_COMMON_FMT,
808 TCP_LOG_TH_FLAGS_COMMON_ARGS);
809 }
810 } else {
811 #define TCP_LOG_TH_FLAGS_PCB_FMT \
812 TCP_LOG_TH_FLAGS_COMMON_FMT \
813 "rtt: %u.%u ms " \
814 "rttvar: %u.%u ms " \
815 "syn rxmit: %u " \
816 "pkt rxmit: %u " \
817 "so_error: %d " \
818 "svc/tc: %u "
819
820 #define TCP_LOG_TH_FLAGS_PCB_ARGS \
821 TCP_LOG_TH_FLAGS_COMMON_ARGS, \
822 tp->t_srtt >> TCP_RTT_SHIFT, tp->t_srtt - ((tp->t_srtt >> TCP_RTT_SHIFT) << TCP_RTT_SHIFT), \
823 tp->t_rttvar >> TCP_RTTVAR_SHIFT, tp->t_rttvar - ((tp->t_rttvar >> TCP_RTTVAR_SHIFT) << TCP_RTTVAR_SHIFT), \
824 tp->t_stat.synrxtshift, \
825 tp->t_stat.rxmitpkts, \
826 so->so_error, \
827 (so->so_flags1 & SOF1_TC_NET_SERV_TYPE) ? \
828 so->so_netsvctype : so->so_traffic_class
829
830 if (tcp_log_level_info == 0) {
831 os_log(OS_LOG_DEFAULT, TCP_LOG_TH_FLAGS_PCB_FMT,
832 TCP_LOG_TH_FLAGS_PCB_ARGS);
833 } else {
834 os_log_info(OS_LOG_DEFAULT, TCP_LOG_TH_FLAGS_PCB_FMT,
835 TCP_LOG_TH_FLAGS_PCB_ARGS);
836 }
837 #undef TCP_LOG_TH_FLAGS_PCB_FMT
838 #undef TCP_LOG_TH_FLAGS_PCB_ARGS
839 }
840 }
841
842 __attribute__((noinline))
843 void
tcp_log_drop_pkt(void * hdr,struct tcphdr * th,struct ifnet * ifp,const char * reason)844 tcp_log_drop_pkt(void *hdr, struct tcphdr *th, struct ifnet *ifp, const char *reason)
845 {
846 char laddr_buf[ADDRESS_STR_LEN];
847 char faddr_buf[ADDRESS_STR_LEN];
848 in_port_t local_port;
849 in_port_t foreign_port;
850 uint8_t thflags;
851 bool outgoing = false; /* This is only for incoming packets */
852
853 if (hdr == NULL || th == NULL) {
854 return;
855 }
856
857 local_port = th->th_dport;
858 foreign_port = th->th_sport;
859 thflags = th->th_flags;
860
861 if ((((thflags & TH_SYN) && (tcp_log_enable_flags & TLEF_THF_SYN)) ||
862 ((thflags & TH_FIN) && (tcp_log_enable_flags & TLEF_THF_FIN)) ||
863 ((thflags & TH_RST) && (tcp_log_enable_flags & TLEF_THF_RST))) == false) {
864 return;
865 }
866
867 if (ifp != NULL && tcp_log_thflags_if_family != 0 && ifp->if_family != tcp_log_thflags_if_family) {
868 return;
869 }
870
871 if (!tcp_log_pkt_addresses(hdr, th, outgoing, laddr_buf, sizeof(laddr_buf), faddr_buf, sizeof(faddr_buf))) {
872 return;
873 }
874
875 /* Do not log too much */
876 if (tcp_log_is_rate_limited()) {
877 return;
878 }
879
880 #define TCP_LOG_DROP_PKT_FMT \
881 "tcp drop incoming control packet " \
882 TCP_LOG_TH_FLAGS_COMMON_FMT \
883 "reason: %s"
884
885 #define TCP_LOG_DROP_PKT_ARGS \
886 TCP_LOG_TH_FLAGS_COMMON_ARGS, \
887 reason != NULL ? reason : ""
888
889 if (tcp_log_level_info == 0) {
890 os_log(OS_LOG_DEFAULT, TCP_LOG_DROP_PKT_FMT,
891 TCP_LOG_DROP_PKT_ARGS);
892 } else {
893 os_log_info(OS_LOG_DEFAULT, TCP_LOG_DROP_PKT_FMT,
894 TCP_LOG_DROP_PKT_ARGS);
895 }
896 #undef TCP_LOG_DROP_PKT_FMT
897 #undef TCP_LOG_DROP_PKT_ARGS
898 }
899
900 __attribute__((noinline))
901 void
tcp_log_message(const char * func_name,int line_no,struct tcpcb * tp,const char * format,...)902 tcp_log_message(const char *func_name, int line_no, struct tcpcb *tp, const char *format, ...)
903 {
904 struct inpcb *inp;
905 struct socket *so;
906 struct ifnet *ifp;
907 char laddr_buf[ADDRESS_STR_LEN];
908 char faddr_buf[ADDRESS_STR_LEN];
909 in_port_t local_port;
910 in_port_t foreign_port;
911 char message[256];
912
913 if (tp == NULL || tp->t_inpcb == NULL || tp->t_inpcb->inp_socket == NULL) {
914 return;
915 }
916
917 /* Do not log too much */
918 if (tcp_log_is_rate_limited()) {
919 return;
920 }
921 inp = tp->t_inpcb;
922 so = inp->inp_socket;
923
924 local_port = inp->inp_lport;
925 foreign_port = inp->inp_fport;
926
927 ifp = inp->inp_last_outifp != NULL ? inp->inp_last_outifp :
928 inp->inp_boundifp != NULL ? inp->inp_boundifp : NULL;
929
930 tcp_log_inp_addresses(inp, laddr_buf, sizeof(laddr_buf), faddr_buf, sizeof(faddr_buf));
931
932 va_list ap;
933 va_start(ap, format);
934 vsnprintf(message, sizeof(message), format, ap);
935 va_end(ap);
936
937 #define TCP_LOG_MESSAGE_FMT \
938 "tcp (%s:%d) " \
939 TCP_LOG_COMMON_PCB_FMT \
940 "%s"
941
942 #define TCP_LOG_MESSAGE_ARGS \
943 func_name, line_no, \
944 TCP_LOG_COMMON_PCB_ARGS, \
945 message
946
947 if (tcp_log_level_info == 0) {
948 os_log(OS_LOG_DEFAULT, TCP_LOG_MESSAGE_FMT,
949 TCP_LOG_MESSAGE_ARGS);
950 } else {
951 os_log_info(OS_LOG_DEFAULT, TCP_LOG_MESSAGE_FMT,
952 TCP_LOG_MESSAGE_ARGS);
953 }
954 #undef TCP_LOG_MESSAGE_FMT
955 #undef TCP_LOG_MESSAGE_ARGS
956 }
957
958 #if SKYWALK
959 __attribute__((noinline))
960 void
tcp_log_fsw_flow(const char * func_name,int line_no,struct tcpcb * tp,const char * format,...)961 tcp_log_fsw_flow(const char *func_name, int line_no, struct tcpcb *tp, const char *format, ...)
962 {
963 struct inpcb *inp;
964 struct socket *so;
965 struct ifnet *ifp;
966 char laddr_buf[ADDRESS_STR_LEN];
967 char faddr_buf[ADDRESS_STR_LEN];
968 in_port_t local_port;
969 in_port_t foreign_port;
970 uuid_string_t flow_uuid_str;
971 char message[256];
972
973 if (tp == NULL || tp->t_inpcb == NULL || tp->t_inpcb->inp_socket == NULL) {
974 return;
975 }
976
977 /* Do not log too much */
978 if (tcp_log_is_rate_limited()) {
979 return;
980 }
981 inp = tp->t_inpcb;
982 so = inp->inp_socket;
983
984 local_port = inp->inp_lport;
985 foreign_port = inp->inp_fport;
986
987 ifp = inp->inp_last_outifp != NULL ? inp->inp_last_outifp :
988 inp->inp_boundifp != NULL ? inp->inp_boundifp : NULL;
989
990 tcp_log_inp_addresses(inp, laddr_buf, sizeof(laddr_buf), faddr_buf, sizeof(faddr_buf));
991
992 uuid_unparse_upper(tp->t_flow_uuid, flow_uuid_str);
993
994 va_list ap;
995 va_start(ap, format);
996 vsnprintf(message, sizeof(message), format, ap);
997 va_end(ap);
998
999 #define TCP_LOG_FSW_FLOW_MESSAGE_FMT \
1000 "tcp (%s:%d) " \
1001 TCP_LOG_COMMON_PCB_FMT \
1002 "flow %s %s"
1003
1004 #define TCP_LOG_FSW_FLOW_MESSAGE_ARGS \
1005 func_name, line_no, \
1006 TCP_LOG_COMMON_PCB_ARGS, \
1007 flow_uuid_str, \
1008 message
1009
1010 if (tcp_log_level_info == 0) {
1011 os_log(OS_LOG_DEFAULT, TCP_LOG_FSW_FLOW_MESSAGE_FMT,
1012 TCP_LOG_FSW_FLOW_MESSAGE_ARGS);
1013 } else {
1014 os_log_info(OS_LOG_DEFAULT, TCP_LOG_FSW_FLOW_MESSAGE_FMT,
1015 TCP_LOG_FSW_FLOW_MESSAGE_ARGS);
1016 }
1017 #undef TCP_LOG_FSW_FLOW_MESSAGE_FMT
1018 #undef TCP_LOG_FSW_FLOW_MESSAGE_ARGS
1019 }
1020 #endif /* SKYWALK */
1021