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