bsd/netinet/tcp_log.c

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