xref: /xnu-11215.41.3/bsd/netinet/udp_log.c (revision 33de042d024d46de5ff4e89f2471de6608e37fa4)
1 /*
2  * Copyright (c) 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 
39 #include <netinet/inp_log.h>
40 #include <netinet/in_pcb.h>
41 
42 #include <netinet/udp_log.h>
43 #include <netinet/udp_var.h>
44 
45 SYSCTL_NODE(_net_inet_udp, OID_AUTO, log, CTLFLAG_RW | CTLFLAG_LOCKED, 0,
46     "UDP");
47 
48 #if (DEVELOPMENT || DEBUG)
49 #define UDP_LOG_ENABLE_DEFAULT \
50     (ULEF_CONNECTION | ULEF_DST_LOCAL | ULEF_DST_GW)
51 #else /* (DEVELOPMENT || DEBUG) */
52 #define UDP_LOG_ENABLE_DEFAULT 0
53 #endif /* (DEVELOPMENT || DEBUG) */
54 
55 uint32_t udp_log_enable_flags = UDP_LOG_ENABLE_DEFAULT;
56 SYSCTL_UINT(_net_inet_udp_log, OID_AUTO, enable,
57     CTLFLAG_RW | CTLFLAG_LOCKED, &udp_log_enable_flags, 0, "");
58 
59 
60 /*
61  * The following is a help to describe the values of the flags
62  */
63 #define X(name, value, description, ...) #description ":" #value " "
64 SYSCTL_STRING(_net_inet_udp_log, OID_AUTO, enable_usage, CTLFLAG_RD | CTLFLAG_LOCKED,
65     UDP_ENABLE_FLAG_LIST, 0, "");
66 #undef X
67 
68 /*
69  *
70  */
71 static int sysctl_udp_log_port SYSCTL_HANDLER_ARGS;
72 
73 uint16_t udp_log_local_port_included = 0;
74 SYSCTL_PROC(_net_inet_udp_log, OID_AUTO, local_port_included,
75     CTLFLAG_RW | CTLFLAG_LOCKED,
76     &udp_log_local_port_included, 0, &sysctl_udp_log_port, "UI", "");
77 
78 uint16_t udp_log_remote_port_included = 0;
79 SYSCTL_PROC(_net_inet_udp_log, OID_AUTO, remote_port_included,
80     CTLFLAG_RW | CTLFLAG_LOCKED,
81     &udp_log_remote_port_included, 0, &sysctl_udp_log_port, "UI", "");
82 
83 uint16_t udp_log_local_port_excluded = 0;
84 SYSCTL_PROC(_net_inet_udp_log, OID_AUTO, local_port_excluded,
85     CTLFLAG_RW | CTLFLAG_LOCKED,
86     &udp_log_local_port_excluded, 0, &sysctl_udp_log_port, "UI", "");
87 
88 uint16_t udp_log_remote_port_excluded = 0;
89 SYSCTL_PROC(_net_inet_udp_log, OID_AUTO, remote_port_excluded,
90     CTLFLAG_RW | CTLFLAG_LOCKED,
91     &udp_log_remote_port_excluded, 0, &sysctl_udp_log_port, "UI", "");
92 
93 #define UDP_LOG_RATE_LIMIT 1000
94 static unsigned int udp_log_rate_limit = UDP_LOG_RATE_LIMIT;
95 SYSCTL_UINT(_net_inet_udp_log, OID_AUTO, rate_limit,
96     CTLFLAG_RW | CTLFLAG_LOCKED, &udp_log_rate_limit, 0, "");
97 
98 /* 1 minute by default */
99 #define UDP_LOG_RATE_DURATION 60
100 static unsigned int udp_log_rate_duration = UDP_LOG_RATE_DURATION;
101 SYSCTL_UINT(_net_inet_udp_log, OID_AUTO, rate_duration,
102     CTLFLAG_RW | CTLFLAG_LOCKED, &udp_log_rate_duration, 0, "");
103 
104 static unsigned long udp_log_rate_max = 0;
105 SYSCTL_ULONG(_net_inet_udp_log, OID_AUTO, rate_max,
106     CTLFLAG_RD | CTLFLAG_LOCKED, &udp_log_rate_max, "");
107 
108 static unsigned long udp_log_rate_exceeded_total = 0;
109 SYSCTL_ULONG(_net_inet_udp_log, OID_AUTO, rate_exceeded_total,
110     CTLFLAG_RD | CTLFLAG_LOCKED, &udp_log_rate_exceeded_total, "");
111 
112 static unsigned long udp_log_rate_current = 0;
113 SYSCTL_ULONG(_net_inet_udp_log, OID_AUTO, rate_current,
114     CTLFLAG_RD | CTLFLAG_LOCKED, &udp_log_rate_current, "");
115 
116 static bool udp_log_rate_exceeded_logged = false;
117 
118 static uint64_t udp_log_current_period = 0;
119 
120 #define ADDRESS_STR_LEN (MAX_IPv6_STR_LEN + 6)
121 
122 
123 #define UDP_LOG_COMMON_FMT \
124 	    "[%s:%u<->%s:%u] " \
125 	    "interface: %s " \
126 	    "(skipped: %lu)\n"
127 
128 #define UDP_LOG_COMMON_ARGS \
129 	laddr_buf, ntohs(local_port), faddr_buf, ntohs(foreign_port), \
130 	    ifp != NULL ? if_name(ifp) : "", \
131 	    udp_log_rate_exceeded_total
132 
133 #define UDP_LOG_COMMON_PCB_FMT \
134 	UDP_LOG_COMMON_FMT \
135 	"so_gencnt: %llu " \
136 	"so_state: 0x%04x " \
137 	"process: %s:%u "
138 
139 #define UDP_LOG_COMMON_PCB_ARGS \
140 	UDP_LOG_COMMON_ARGS, \
141 	so != NULL ? so->so_gencnt : 0, \
142 	so != NULL ? so->so_state : 0, \
143 	inp->inp_last_proc_name, so->last_pid
144 
145 /*
146  * Returns true when above the rate limit
147  */
148 static bool
udp_log_is_rate_limited(void)149 udp_log_is_rate_limited(void)
150 {
151 	uint64_t current_net_period = net_uptime();
152 
153 	/* When set to zero it means to reset to default */
154 	if (udp_log_rate_duration == 0) {
155 		udp_log_rate_duration = UDP_LOG_RATE_DURATION;
156 	}
157 	if (udp_log_rate_limit == 0) {
158 		udp_log_rate_duration = UDP_LOG_RATE_LIMIT;
159 	}
160 
161 	if (current_net_period > udp_log_current_period + udp_log_rate_duration) {
162 		if (udp_log_rate_current > udp_log_rate_max) {
163 			udp_log_rate_max = udp_log_rate_current;
164 		}
165 		udp_log_current_period = current_net_period;
166 		udp_log_rate_current = 0;
167 		udp_log_rate_exceeded_logged = false;
168 	}
169 
170 	udp_log_rate_current += 1;
171 
172 	if (udp_log_rate_current > (unsigned long) udp_log_rate_limit) {
173 		udp_log_rate_exceeded_total += 1;
174 		return true;
175 	}
176 
177 	return false;
178 }
179 
180 static bool
udp_log_port_allowed(struct inpcb * inp)181 udp_log_port_allowed(struct inpcb *inp)
182 {
183 	if (ntohs(inp->inp_lport) == udp_log_local_port_included ||
184 	    ntohs(inp->inp_fport) == udp_log_remote_port_included) {
185 		return true;
186 	} else {
187 		return false;
188 	}
189 
190 	if (ntohs(inp->inp_lport) == udp_log_local_port_excluded ||
191 	    ntohs(inp->inp_fport) == udp_log_remote_port_excluded) {
192 		return false;
193 	}
194 
195 	return true;
196 }
197 
198 __attribute__((noinline))
199 void
udp_log_bind(struct inpcb * inp,const char * event,int error)200 udp_log_bind(struct inpcb *inp, const char *event, int error)
201 {
202 	struct socket *so;
203 	struct ifnet *ifp;
204 	char laddr_buf[ADDRESS_STR_LEN];
205 	char faddr_buf[ADDRESS_STR_LEN];
206 	in_port_t local_port;
207 	in_port_t foreign_port;
208 
209 	if (inp == NULL || inp->inp_socket == NULL || event == NULL) {
210 		return;
211 	}
212 
213 	/* Do not log too much */
214 	if (udp_log_is_rate_limited()) {
215 		return;
216 	}
217 
218 	if (!udp_log_port_allowed(inp)) {
219 		return;
220 	}
221 
222 	inp->inp_flags2 &= ~INP2_LOGGED_SUMMARY;
223 	inp->inp_flags2 |= INP2_LOGGING_ENABLED;
224 
225 	so = inp->inp_socket;
226 
227 	local_port = inp->inp_lport;
228 	foreign_port = inp->inp_fport;
229 
230 	ifp = inp->inp_last_outifp != NULL ? inp->inp_last_outifp :
231 	    inp->inp_boundifp != NULL ? inp->inp_boundifp : NULL;
232 
233 	inp_log_addresses(inp, laddr_buf, sizeof(laddr_buf), faddr_buf, sizeof(faddr_buf));
234 
235 #define UDP_LOG_BIND_FMT \
236 	    "udp %s: " \
237 	    UDP_LOG_COMMON_PCB_FMT \
238 	    "bytes in/out: %llu/%llu " \
239 	    "pkts in/out: %llu/%llu " \
240 	    "error: %d " \
241 	    "so_error: %d " \
242 	    "svc/tc: %u"
243 
244 #define UDP_LOG_BIND_ARGS \
245 	    event, \
246 	    UDP_LOG_COMMON_PCB_ARGS, \
247 	    inp->inp_stat->rxbytes, inp->inp_stat->txbytes, \
248 	    inp->inp_stat->rxpackets, inp->inp_stat->txpackets, \
249 	    error, \
250 	    so->so_error, \
251 	    (so->so_flags1 & SOF1_TC_NET_SERV_TYPE) ? so->so_netsvctype : so->so_traffic_class
252 
253 	os_log(OS_LOG_DEFAULT, UDP_LOG_BIND_FMT,
254 	    UDP_LOG_BIND_ARGS);
255 
256 #undef UDP_LOG_BIND_FMT
257 #undef UDP_LOG_BIND_ARGS
258 }
259 
260 __attribute__((noinline))
261 void
udp_log_connection(struct inpcb * inp,const char * event,int error)262 udp_log_connection(struct inpcb *inp, const char *event, int error)
263 {
264 	struct socket *so;
265 	struct ifnet *ifp;
266 	char laddr_buf[ADDRESS_STR_LEN];
267 	char faddr_buf[ADDRESS_STR_LEN];
268 	in_port_t local_port;
269 	in_port_t foreign_port;
270 
271 	if (inp == NULL || inp->inp_socket == NULL || event == NULL) {
272 		return;
273 	}
274 
275 	/* Do not log too much */
276 	if (udp_log_is_rate_limited()) {
277 		return;
278 	}
279 
280 	if (!udp_log_port_allowed(inp)) {
281 		return;
282 	}
283 
284 	/* Clear the logging flags as one may reconnect an UDP socket */
285 	inp->inp_flags2 &= ~INP2_LOGGED_SUMMARY;
286 	inp->inp_flags2 |= INP2_LOGGING_ENABLED;
287 
288 	so = inp->inp_socket;
289 
290 	local_port = inp->inp_lport;
291 	foreign_port = inp->inp_fport;
292 
293 	ifp = inp->inp_last_outifp != NULL ? inp->inp_last_outifp :
294 	    inp->inp_boundifp != NULL ? inp->inp_boundifp : NULL;
295 
296 	inp_log_addresses(inp, laddr_buf, sizeof(laddr_buf), faddr_buf, sizeof(faddr_buf));
297 
298 #define UDP_LOG_CONNECT_FMT \
299 	    "udp %s: " \
300 	    UDP_LOG_COMMON_PCB_FMT \
301 	    "bytes in/out: %llu/%llu " \
302 	    "pkts in/out: %llu/%llu " \
303 	    "error: %d " \
304 	    "so_error: %d " \
305 	    "svc/tc: %u " \
306 	    "flow: 0x%x"
307 
308 #define UDP_LOG_CONNECT_ARGS \
309 	    event, \
310 	    UDP_LOG_COMMON_PCB_ARGS, \
311 	    inp->inp_stat->rxbytes, inp->inp_stat->txbytes, \
312 	    inp->inp_stat->rxpackets, inp->inp_stat->txpackets, \
313 	    error, \
314 	    so->so_error, \
315 	    (so->so_flags1 & SOF1_TC_NET_SERV_TYPE) ? so->so_netsvctype : so->so_traffic_class, \
316 	    inp->inp_flowhash
317 
318 	os_log(OS_LOG_DEFAULT, UDP_LOG_CONNECT_FMT,
319 	    UDP_LOG_CONNECT_ARGS);
320 
321 #undef UDP_LOG_CONNECT_FMT
322 #undef UDP_LOG_CONNECT_ARGS
323 }
324 
325 __attribute__((noinline))
326 void
udp_log_connection_summary(struct inpcb * inp)327 udp_log_connection_summary(struct inpcb *inp)
328 {
329 	struct socket *so;
330 	struct ifnet *ifp;
331 	clock_sec_t duration_secs = 0;
332 	clock_usec_t duration_microsecs = 0;
333 	clock_sec_t connection_secs = 0;
334 	clock_usec_t connection_microsecs = 0;
335 	char laddr_buf[ADDRESS_STR_LEN];
336 	char faddr_buf[ADDRESS_STR_LEN];
337 	in_port_t local_port;
338 	in_port_t foreign_port;
339 
340 	if (inp == NULL || inp->inp_socket == NULL) {
341 		return;
342 	}
343 	if ((inp->inp_flags2 & INP2_LOGGING_ENABLED) == 0) {
344 		return;
345 	}
346 	/* Make sure the summary is logged once */
347 	if (inp->inp_flags2 & INP2_LOGGED_SUMMARY) {
348 		return;
349 	}
350 	inp->inp_flags2 |= INP2_LOGGED_SUMMARY;
351 	inp->inp_flags2 &= ~INP2_LOGGING_ENABLED;
352 
353 	/* Do not log too much */
354 	if (udp_log_is_rate_limited()) {
355 		return;
356 	}
357 	so = inp->inp_socket;
358 
359 	local_port = inp->inp_lport;
360 	foreign_port = inp->inp_fport;
361 
362 
363 	/*
364 	 * inp_start_timestamp is when the UDP socket was open.
365 	 *
366 	 * inp_connect_timestamp is when the connection started on
367 	 */
368 	uint64_t now = mach_continuous_time();
369 	if (inp->inp_start_timestamp > 0) {
370 		uint64_t duration = now - inp->inp_start_timestamp;
371 
372 		absolutetime_to_microtime(duration, &duration_secs, &duration_microsecs);
373 	}
374 	if (inp->inp_connect_timestamp > 0) {
375 		uint64_t duration = now - inp->inp_connect_timestamp;
376 
377 		absolutetime_to_microtime(duration, &connection_secs, &connection_microsecs);
378 	}
379 
380 	ifp = inp->inp_last_outifp != NULL ? inp->inp_last_outifp :
381 	    inp->inp_boundifp != NULL ? inp->inp_boundifp : NULL;
382 
383 	inp_log_addresses(inp, laddr_buf, sizeof(laddr_buf), faddr_buf, sizeof(faddr_buf));
384 
385 	/*
386 	 * Need to use 2 log messages because the size of the summary
387 	 */
388 
389 #define UDP_LOG_CONNECTION_SUMMARY_FMT \
390 	    "udp_connection_summary " \
391 	    UDP_LOG_COMMON_PCB_FMT \
392 	    "Duration: %lu.%03d sec " \
393 	    "Conn_Time: %lu.%03d sec " \
394 	    "bytes in/out: %llu/%llu " \
395 	    "pkts in/out: %llu/%llu " \
396 	    "rxnospace pkts/bytes: %llu/%llu " \
397 	    "so_error: %d " \
398 	    "svc/tc: %u " \
399 	    "flow: 0x%x"
400 
401 #define UDP_LOG_CONNECTION_SUMMARY_ARGS \
402 	    UDP_LOG_COMMON_PCB_ARGS, \
403 	    duration_secs, duration_microsecs / 1000, \
404 	    connection_secs, connection_microsecs / 1000, \
405 	    inp->inp_stat->rxbytes, inp->inp_stat->txbytes, \
406 	    inp->inp_stat->rxpackets, inp->inp_stat->txpackets, \
407 	    so->so_tc_stats[SO_STATS_SBNOSPACE].rxpackets, \
408 	    so->so_tc_stats[SO_STATS_SBNOSPACE].rxbytes, \
409 	    so->so_error, \
410 	    (so->so_flags1 & SOF1_TC_NET_SERV_TYPE) ? so->so_netsvctype : so->so_traffic_class, \
411 	    inp->inp_flowhash
412 
413 	os_log(OS_LOG_DEFAULT, UDP_LOG_CONNECTION_SUMMARY_FMT,
414 	    UDP_LOG_CONNECTION_SUMMARY_ARGS);
415 #undef UDP_LOG_CONNECTION_SUMMARY_FMT
416 #undef UDP_LOG_CONNECTION_SUMMARY_ARGS
417 
418 #define UDP_LOG_CONNECTION_SUMMARY_FMT \
419 	    "udp_connection_summary " \
420 	    UDP_LOG_COMMON_PCB_FMT \
421 	    "flowctl: %lluus (%llux) "
422 
423 #define UDP_LOG_CONNECTION_SUMMARY_ARGS \
424 	    UDP_LOG_COMMON_PCB_ARGS, \
425 	    inp->inp_fadv_total_time, \
426 	    inp->inp_fadv_cnt
427 
428 	os_log(OS_LOG_DEFAULT, UDP_LOG_CONNECTION_SUMMARY_FMT,
429 	    UDP_LOG_CONNECTION_SUMMARY_ARGS);
430 #undef UDP_LOG_CONNECTION_SUMMARY_FMT
431 #undef UDP_LOG_CONNECTION_SUMMARY_ARGS
432 }
433 
434 static int
435 sysctl_udp_log_port SYSCTL_HANDLER_ARGS
436 {
437 #pragma unused(arg1, arg2)
438 	int error;
439 	int new_value = *(int *)oidp->oid_arg1;
440 
441 	error = sysctl_handle_int(oidp, &new_value, 0, req);
442 	if (error != 0) {
443 		return error;
444 	}
445 	if (new_value < 0 || new_value > UINT16_MAX) {
446 		return EINVAL;
447 	}
448 	*(uint16_t *)oidp->oid_arg1 = (uint16_t)new_value;
449 
450 	return 0;
451 }
452