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