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 #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)
  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
 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
 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 void
 223 tcp_log_rtt_info(const char *func_name, int line_no, struct tcpcb *tp)
 224 {
 225         struct inpcb *inp = tp->t_inpcb;
 226         struct socket *so = inp->inp_socket;
 227         struct ifnet *ifp;
 228         char laddr_buf[ADDRESS_STR_LEN];
 229         char faddr_buf[ADDRESS_STR_LEN];
 230         in_port_t local_port = inp->inp_lport;
 231         in_port_t foreign_port = inp->inp_fport;
 232
 233         /* Do not log too much */
 234         if (tcp_log_is_rate_limited()) {
 235                 return;
 236         }
 237
 238         ifp = inp->inp_last_outifp != NULL ? inp->inp_last_outifp :
 239             inp->inp_boundifp != NULL ? inp->inp_boundifp : NULL;
 240
 241         tcp_log_inp_addresses(inp, laddr_buf, sizeof(laddr_buf), faddr_buf, sizeof(faddr_buf));
 242
 243         os_log(OS_LOG_DEFAULT,
 244             "tcp_rtt_info (%s:%d) "
 245             TCP_LOG_COMMON_PCB_FMT
 246             "rttcur: %u ms srtt: %u ms rttvar: %u ms rttmin: %u ms rxtcur: %u rxtshift: %u",
 247             func_name, line_no,
 248             TCP_LOG_COMMON_PCB_ARGS,
 249             tp->t_rttcur, tp->t_srtt >> TCP_RTT_SHIFT,
 250             tp->t_rttvar >> TCP_RTTVAR_SHIFT,
 251             tp->t_rttmin, tp->t_rxtcur, tp->t_rxtshift);
 252 }
 253
 254 void
 255 tcp_log_rt_rtt(const char *func_name, int line_no, struct tcpcb *tp,
 256     struct rtentry *rt)
 257 {
 258         struct inpcb *inp = tp->t_inpcb;
 259         struct socket *so = inp->inp_socket;
 260         struct ifnet *ifp;
 261         char laddr_buf[ADDRESS_STR_LEN];
 262         char faddr_buf[ADDRESS_STR_LEN];
 263         in_port_t local_port = inp->inp_lport;
 264         in_port_t foreign_port = inp->inp_fport;
 265
 266         /* Do not log too much */
 267         if (tcp_log_is_rate_limited()) {
 268                 return;
 269         }
 270
 271         ifp = inp->inp_last_outifp != NULL ? inp->inp_last_outifp :
 272             inp->inp_boundifp != NULL ? inp->inp_boundifp : NULL;
 273
 274         tcp_log_inp_addresses(inp, laddr_buf, sizeof(laddr_buf), faddr_buf, sizeof(faddr_buf));
 275
 276         /*
 277          * Log RTT values in milliseconds
 278          */
 279         os_log(OS_LOG_DEFAULT,
 280             "tcp_rt_rtt (%s:%d) "
 281             TCP_LOG_COMMON_PCB_FMT
 282             "rt_rmx: RTV_RTT: %d ms rtt: %u ms rttvar: %u ms",
 283             func_name, line_no,
 284             TCP_LOG_COMMON_PCB_ARGS,
 285             (rt->rt_rmx.rmx_locks & RTV_RTT),
 286             rt->rt_rmx.rmx_rtt / (RTM_RTTUNIT / TCP_RETRANSHZ),
 287             rt->rt_rmx.rmx_rttvar / (RTM_RTTUNIT / TCP_RETRANSHZ));
 288 }
 289
 290 void
 291 tcp_log_rtt_change(const char *func_name, int line_no, struct tcpcb *tp,
 292     int old_srtt, int old_rttvar)
 293 {
 294         int srtt_diff;
 295         int rttvar_diff;
 296
 297         srtt_diff = ABS(tp->t_srtt  - old_srtt) >> TCP_RTT_SHIFT;
 298         rttvar_diff =
 299             ABS((tp->t_rttvar - old_rttvar) >> TCP_RTTVAR_SHIFT);
 300         if (srtt_diff >= 1000 || rttvar_diff >= 500) {
 301                 struct inpcb *inp = tp->t_inpcb;
 302                 struct socket *so = inp->inp_socket;
 303                 struct ifnet *ifp;
 304                 char laddr_buf[ADDRESS_STR_LEN];
 305                 char faddr_buf[ADDRESS_STR_LEN];
 306                 in_port_t local_port = inp->inp_lport;
 307                 in_port_t foreign_port = inp->inp_fport;
 308
 309                 /* Do not log too much */
 310                 if (tcp_log_is_rate_limited()) {
 311                         return;
 312                 }
 313
 314                 ifp = inp->inp_last_outifp != NULL ? inp->inp_last_outifp :
 315                     inp->inp_boundifp != NULL ? inp->inp_boundifp : NULL;
 316
 317                 tcp_log_inp_addresses(inp, laddr_buf, sizeof(laddr_buf), faddr_buf, sizeof(faddr_buf));
 318
 319                 os_log(OS_LOG_DEFAULT,
 320                     "tcp_rtt_change (%s:%d) "
 321                     TCP_LOG_COMMON_PCB_FMT
 322                     "srtt: %u ms old_rtt: %u ms "
 323                     "rttvar: %u old_rttvar: %u ms ",
 324                     func_name, line_no,
 325                     TCP_LOG_COMMON_PCB_ARGS,
 326                     tp->t_srtt >> TCP_RTT_SHIFT,
 327                     old_srtt >> TCP_RTT_SHIFT,
 328                     tp->t_rttvar >> TCP_RTTVAR_SHIFT,
 329                     old_rttvar >> TCP_RTTVAR_SHIFT);
 330         }
 331 }
 332
 333 void
 334 tcp_log_keepalive(const char *func_name, int line_no, struct tcpcb *tp,
 335     int32_t idle_time)
 336 {
 337         struct inpcb *inp = tp->t_inpcb;
 338         struct socket *so = inp->inp_socket;
 339         struct ifnet *ifp;
 340         char laddr_buf[ADDRESS_STR_LEN];
 341         char faddr_buf[ADDRESS_STR_LEN];
 342         in_port_t local_port = inp->inp_lport;
 343         in_port_t foreign_port = inp->inp_fport;
 344
 345         /* Do not log too much */
 346         if (tcp_log_is_rate_limited()) {
 347                 return;
 348         }
 349
 350         ifp = inp->inp_last_outifp != NULL ? inp->inp_last_outifp :
 351             inp->inp_boundifp != NULL ? inp->inp_boundifp : NULL;
 352
 353         tcp_log_inp_addresses(inp, laddr_buf, sizeof(laddr_buf), faddr_buf, sizeof(faddr_buf));
 354
 355         os_log(OS_LOG_DEFAULT,
 356             "tcp_keepalive (%s:%d) "
 357             TCP_LOG_COMMON_PCB_FMT
 358             "snd_una: %u snd_max: %u "
 359             "SO_KA: %d RSTALL: %d TFOPRB: %d idle_time: %u "
 360             "KIDLE: %d KINTV: %d KCNT: %d",
 361             func_name, line_no,
 362             TCP_LOG_COMMON_PCB_ARGS,
 363             tp->snd_una, tp->snd_max,
 364             tp->t_inpcb->inp_socket->so_options & SO_KEEPALIVE,
 365             tp->t_flagsext & TF_DETECT_READSTALL,
 366             tp->t_tfo_probe_state == TFO_PROBE_PROBING,
 367             idle_time,
 368             TCP_CONN_KEEPIDLE(tp), TCP_CONN_KEEPINTVL(tp),
 369             TCP_CONN_KEEPCNT(tp));
 370 }
 371
 372
 373 void
 374 tcp_log_connection(struct tcpcb *tp, const char *event, int error)
 375 {
 376         struct inpcb *inp;
 377         struct socket *so;
 378         struct ifnet *ifp;
 379         char laddr_buf[ADDRESS_STR_LEN];
 380         char faddr_buf[ADDRESS_STR_LEN];
 381         in_port_t local_port;
 382         in_port_t foreign_port;
 383
 384         if (tp == NULL || tp->t_inpcb == NULL || tp->t_inpcb->inp_socket == NULL || event == NULL) {
 385                 return;
 386         }
 387
 388         /* Do not log too much */
 389         if (tcp_log_is_rate_limited()) {
 390                 return;
 391         }
 392         inp = tp->t_inpcb;
 393         so = inp->inp_socket;
 394
 395         local_port = inp->inp_lport;
 396         foreign_port = inp->inp_fport;
 397
 398         ifp = inp->inp_last_outifp != NULL ? inp->inp_last_outifp :
 399             inp->inp_boundifp != NULL ? inp->inp_boundifp : NULL;
 400
 401         tcp_log_inp_addresses(inp, laddr_buf, sizeof(laddr_buf), faddr_buf, sizeof(faddr_buf));
 402
 403 #define TCP_LOG_CONNECT_FMT \
 404             "tcp %s: " \
 405             TCP_LOG_COMMON_PCB_FMT \
 406             "rtt: %u.%u ms " \
 407             "rttvar: %u.%u ms " \
 408             "error: %d " \
 409             "so_error: %d " \
 410             "svc/tc: %u"
 411
 412 #define TCP_LOG_CONNECT_ARGS \
 413             event, \
 414             TCP_LOG_COMMON_PCB_ARGS, \
 415             tp->t_srtt >> TCP_RTT_SHIFT, tp->t_srtt - ((tp->t_srtt >> TCP_RTT_SHIFT) << TCP_RTT_SHIFT), \
 416             tp->t_rttvar >> TCP_RTTVAR_SHIFT, tp->t_rttvar - ((tp->t_rttvar >> TCP_RTTVAR_SHIFT) << TCP_RTTVAR_SHIFT), \
 417             error, \
 418             so->so_error, \
 419             (so->so_flags1 & SOF1_TC_NET_SERV_TYPE) ? so->so_netsvctype : so->so_traffic_class
 420
 421         if (so->so_head == NULL) {
 422                 if (tcp_log_level_info == 0) {
 423                         os_log(OS_LOG_DEFAULT, TCP_LOG_CONNECT_FMT,
 424                             TCP_LOG_CONNECT_ARGS);
 425                 } else {
 426                         os_log_info(OS_LOG_DEFAULT, TCP_LOG_CONNECT_FMT,
 427                             TCP_LOG_CONNECT_ARGS);
 428                 }
 429         } else {
 430 #define TCP_LOG_CONN_Q_FMT \
 431         "so_qlimit: %d "\
 432         "so_qlen: %d "\
 433         "so_incqlen: %d "
 434
 435 #define TCP_LOG_CONN_Q_ARGS \
 436         so->so_head->so_qlimit, \
 437         so->so_head->so_qlen, \
 438         so->so_head->so_incqlen
 439
 440                 if (tcp_log_level_info == 0) {
 441                         os_log(OS_LOG_DEFAULT, TCP_LOG_CONNECT_FMT "\n" TCP_LOG_CONN_Q_FMT,
 442                             TCP_LOG_CONNECT_ARGS, TCP_LOG_CONN_Q_ARGS);
 443                 } else {
 444                         os_log_info(OS_LOG_DEFAULT, TCP_LOG_CONNECT_FMT "\n" TCP_LOG_CONN_Q_FMT,
 445                             TCP_LOG_CONNECT_ARGS, TCP_LOG_CONN_Q_ARGS);
 446                 }
 447 #undef TCP_LOG_CONN_Q_FMT
 448 #undef TCP_LOG_CONN_Q_ARGS
 449         }
 450 #undef TCP_LOG_CONNECT_FMT
 451 #undef TCP_LOG_CONNECT_ARGS
 452 }
 453
 454 void
 455 tcp_log_listen(struct tcpcb *tp, int error)
 456 {
 457         struct inpcb *inp = tp->t_inpcb;
 458         struct socket *so = inp->inp_socket;
 459         struct ifnet *ifp;
 460         char laddr_buf[ADDRESS_STR_LEN];
 461         char faddr_buf[ADDRESS_STR_LEN];
 462         in_port_t local_port;
 463         in_port_t foreign_port;
 464
 465         if (tp == NULL || tp->t_inpcb == NULL || tp->t_inpcb->inp_socket == NULL) {
 466                 return;
 467         }
 468
 469         /* Do not log too much */
 470         if (tcp_log_is_rate_limited()) {
 471                 return;
 472         }
 473         inp = tp->t_inpcb;
 474         so = inp->inp_socket;
 475
 476         local_port = inp->inp_lport;
 477         foreign_port = inp->inp_fport;
 478
 479         ifp = inp->inp_last_outifp != NULL ? inp->inp_last_outifp :
 480             inp->inp_boundifp != NULL ? inp->inp_boundifp : NULL;
 481
 482         tcp_log_inp_addresses(inp, laddr_buf, sizeof(laddr_buf), faddr_buf, sizeof(faddr_buf));
 483
 484 #define TCP_LOG_LISTEN_FMT \
 485             "tcp listen: " \
 486             TCP_LOG_COMMON_PCB_FMT \
 487             "so_qlimit: %d "\
 488             "error: %d " \
 489             "so_error: %d " \
 490             "svc/tc: %u"
 491
 492 #define TCP_LOG_LISTEN_ARGS \
 493             TCP_LOG_COMMON_PCB_ARGS, \
 494             so->so_qlimit, \
 495             error, \
 496             so->so_error, \
 497             (so->so_flags1 & SOF1_TC_NET_SERV_TYPE) ? so->so_netsvctype : so->so_traffic_class
 498
 499         if (tcp_log_level_info == 0) {
 500                 os_log(OS_LOG_DEFAULT, TCP_LOG_LISTEN_FMT,
 501                     TCP_LOG_LISTEN_ARGS);
 502         } else {
 503                 os_log_info(OS_LOG_DEFAULT, TCP_LOG_LISTEN_FMT,
 504                     TCP_LOG_LISTEN_ARGS);
 505         }
 506 #undef TCP_LOG_LISTEN_FMT
 507 #undef TCP_LOG_LISTEN_ARGS
 508 }
 509
 510 void
 511 tcp_log_connection_summary(struct tcpcb *tp)
 512 {
 513         struct inpcb *inp;
 514         struct socket *so;
 515         struct ifnet *ifp;
 516         uint32_t conntime = 0;
 517         uint32_t duration = 0;
 518         char laddr_buf[ADDRESS_STR_LEN];
 519         char faddr_buf[ADDRESS_STR_LEN];
 520         in_port_t local_port;
 521         in_port_t foreign_port;
 522
 523         if (tp == NULL || tp->t_inpcb == NULL || tp->t_inpcb->inp_socket == NULL) {
 524                 return;
 525         }
 526
 527         /* Do not log too much */
 528         if (tcp_log_is_rate_limited()) {
 529                 return;
 530         }
 531         inp = tp->t_inpcb;
 532         so = inp->inp_socket;
 533
 534         local_port = inp->inp_lport;
 535         foreign_port = inp->inp_fport;
 536
 537         /* Make sure the summary is logged once */
 538         if (tp->t_flagsext & TF_LOGGED_CONN_SUMMARY) {
 539                 return;
 540         }
 541         tp->t_flagsext |= TF_LOGGED_CONN_SUMMARY;
 542
 543         /*
 544          * t_connect_time is the time when the connection started on
 545          * the first SYN.
 546          *
 547          * t_starttime is when the three way handshake was completed.
 548          */
 549         if (tp->t_connect_time > 0) {
 550                 duration = tcp_now - tp->t_connect_time;
 551
 552                 if (tp->t_starttime > 0) {
 553                         conntime = tp->t_starttime - tp->t_connect_time;
 554                 }
 555         }
 556
 557         ifp = inp->inp_last_outifp != NULL ? inp->inp_last_outifp :
 558             inp->inp_boundifp != NULL ? inp->inp_boundifp : NULL;
 559
 560         tcp_log_inp_addresses(inp, laddr_buf, sizeof(laddr_buf), faddr_buf, sizeof(faddr_buf));
 561
 562 #define TCP_LOG_CONNECTION_SUMMARY_FMT \
 563             "tcp_connection_summary " \
 564             TCP_LOG_COMMON_PCB_FMT \
 565             "Duration: %u.%u sec " \
 566             "Conn_Time: %u.%u sec " \
 567             "syn rxmit: %u\n" \
 568             "bytes in/out: %llu/%llu " \
 569             "pkts in/out: %llu/%llu " \
 570             "rtt: %u.%u ms " \
 571             "rttvar: %u.%u ms " \
 572             "pkt rxmit: %u " \
 573             "ooo pkts: %u dup bytes in: %u ACKs delayed: %u delayed ACKs sent: %u " \
 574             "so_error: %d " \
 575             "svc/tc: %u"
 576
 577 #define TCP_LOG_CONNECTION_SUMMARY_ARGS \
 578             TCP_LOG_COMMON_PCB_ARGS, \
 579             duration / TCP_RETRANSHZ, duration % TCP_RETRANSHZ, \
 580             conntime / TCP_RETRANSHZ, conntime % TCP_RETRANSHZ,  \
 581             tp->t_stat.synrxtshift, \
 582             inp->inp_stat->rxbytes, inp->inp_stat->txbytes, \
 583             inp->inp_stat->rxpackets, inp->inp_stat->txpackets, \
 584             tp->t_srtt >> TCP_RTT_SHIFT, tp->t_srtt - ((tp->t_srtt >> TCP_RTT_SHIFT) << TCP_RTT_SHIFT), \
 585             tp->t_rttvar >> TCP_RTTVAR_SHIFT, tp->t_rttvar - ((tp->t_rttvar >> TCP_RTTVAR_SHIFT) << TCP_RTTVAR_SHIFT), \
 586             tp->t_stat.rxmitpkts, \
 587             tp->t_rcvoopack, tp->t_stat.rxduplicatebytes, tp->t_stat.acks_delayed, tp->t_stat.delayed_acks_sent, \
 588             so->so_error, \
 589             (so->so_flags1 & SOF1_TC_NET_SERV_TYPE) ? so->so_netsvctype : so->so_traffic_class
 590
 591         if (tcp_log_level_info == 0) {
 592                 os_log(OS_LOG_DEFAULT, TCP_LOG_CONNECTION_SUMMARY_FMT,
 593                     TCP_LOG_CONNECTION_SUMMARY_ARGS);
 594         } else {
 595                 os_log_info(OS_LOG_DEFAULT, TCP_LOG_CONNECTION_SUMMARY_FMT,
 596                     TCP_LOG_CONNECTION_SUMMARY_ARGS);
 597         }
 598 #undef TCP_LOG_CONNECTION_SUMMARY_FMT
 599 #undef TCP_LOG_CONNECTION_SUMMARY_ARGS
 600 }
 601
 602 static bool
 603 tcp_log_pkt_addresses(void *hdr, struct tcphdr *th, bool outgoing,
 604     char *lbuf, socklen_t lbuflen, char *fbuf, socklen_t fbuflen)
 605 {
 606         bool isipv6;
 607         uint8_t thflags;
 608
 609         isipv6 = (((struct ip *)hdr)->ip_v == 6);
 610         thflags = th->th_flags;
 611
 612         if (isipv6) {
 613                 struct ip6_hdr *ip6 = (struct ip6_hdr *)hdr;
 614
 615                 if (memcmp(&ip6->ip6_src, &in6addr_loopback, sizeof(struct in6_addr)) == 0 ||
 616                     memcmp(&ip6->ip6_dst, &in6addr_loopback, sizeof(struct in6_addr)) == 0) {
 617                         if (!(tcp_log_enable_flags & TLEF_DST_LOOPBACK)) {
 618                                 return false;
 619                         }
 620                 }
 621
 622                 if (tcp_log_privacy != 0) {
 623                         strlcpy(lbuf, "<IPv6-redacted>", lbuflen);
 624                         strlcpy(fbuf, "<IPv6-redacted>", fbuflen);
 625                 } else if (outgoing) {
 626                         inet_ntop(AF_INET6, &ip6->ip6_src, lbuf, lbuflen);
 627                         inet_ntop(AF_INET6, &ip6->ip6_dst, fbuf, fbuflen);
 628                 } else {
 629                         inet_ntop(AF_INET6, &ip6->ip6_dst, lbuf, lbuflen);
 630                         inet_ntop(AF_INET6, &ip6->ip6_src, fbuf, fbuflen);
 631                 }
 632         } else {
 633                 struct ip *ip = (struct ip *)hdr;
 634
 635                 if (ntohl(ip->ip_src.s_addr) == INADDR_LOOPBACK ||
 636                     ntohl(ip->ip_dst.s_addr) == INADDR_LOOPBACK) {
 637                         if (!(tcp_log_enable_flags & TLEF_DST_LOOPBACK)) {
 638                                 return false;
 639                         }
 640                 }
 641
 642                 if (tcp_log_privacy != 0) {
 643                         strlcpy(lbuf, "<IPv4-redacted>", lbuflen);
 644                         strlcpy(fbuf, "<IPv4-redacted>", fbuflen);
 645                 } else if (outgoing) {
 646                         inet_ntop(AF_INET, (void *)&ip->ip_src.s_addr, lbuf, lbuflen);
 647                         inet_ntop(AF_INET, (void *)&ip->ip_dst.s_addr, fbuf, fbuflen);
 648                 } else {
 649                         inet_ntop(AF_INET, (void *)&ip->ip_dst.s_addr, lbuf, lbuflen);
 650                         inet_ntop(AF_INET, (void *)&ip->ip_src.s_addr, fbuf, fbuflen);
 651                 }
 652         }
 653         return true;
 654 }
 655
 656 /*
 657  * Note: currently only used in the input path
 658  */
 659 void
 660 tcp_log_drop_pcb(void *hdr, struct tcphdr *th, struct tcpcb *tp, bool outgoing, const char *reason)
 661 {
 662         struct inpcb *inp = tp->t_inpcb;
 663         struct socket *so = inp->inp_socket;
 664         struct ifnet *ifp;
 665         char laddr_buf[ADDRESS_STR_LEN];
 666         char faddr_buf[ADDRESS_STR_LEN];
 667         in_port_t local_port;
 668         in_port_t foreign_port;
 669
 670         if (tp == NULL) {
 671                 return;
 672         }
 673
 674         /* Do not log too much */
 675         if (tcp_log_is_rate_limited()) {
 676                 return;
 677         }
 678
 679         /* Use the packet addresses when in the data path */
 680         if (hdr != NULL && th != NULL) {
 681                 if (outgoing) {
 682                         local_port = th->th_sport;
 683                         foreign_port = th->th_dport;
 684                 } else {
 685                         local_port = th->th_dport;
 686                         foreign_port = th->th_sport;
 687                 }
 688                 (void) tcp_log_pkt_addresses(hdr, th, outgoing, laddr_buf, sizeof(laddr_buf), faddr_buf, sizeof(faddr_buf));
 689         } else {
 690                 local_port = inp->inp_lport;
 691                 foreign_port = inp->inp_fport;
 692                 tcp_log_inp_addresses(inp, laddr_buf, sizeof(laddr_buf), faddr_buf, sizeof(faddr_buf));
 693         }
 694
 695         ifp = inp->inp_last_outifp != NULL ? inp->inp_last_outifp :
 696             inp->inp_boundifp != NULL ? inp->inp_boundifp : NULL;
 697
 698 #define TCP_LOG_DROP_PCB_FMT \
 699             "tcp drop %s " \
 700             TCP_LOG_COMMON_PCB_FMT \
 701             "t_state: %s " \
 702             "so_error: %d " \
 703             "reason: %s"
 704
 705 #define TCP_LOG_DROP_PCB_ARGS \
 706             outgoing ? "outgoing" : "incoming", \
 707             TCP_LOG_COMMON_PCB_ARGS, \
 708             tcpstates[tp->t_state], \
 709             so->so_error, \
 710             reason
 711
 712         if (tcp_log_level_info == 0) {
 713                 os_log(OS_LOG_DEFAULT, TCP_LOG_DROP_PCB_FMT,
 714                     TCP_LOG_DROP_PCB_ARGS);
 715         } else {
 716                 os_log_info(OS_LOG_DEFAULT, TCP_LOG_DROP_PCB_FMT,
 717                     TCP_LOG_DROP_PCB_ARGS);
 718         }
 719 #undef TCP_LOG_DROP_PCB_FMT
 720 #undef TCP_LOG_DROP_PCB_ARGS
 721 }
 722
 723 #define TCP_LOG_TH_FLAGS_COMMON_FMT \
 724         "tcp control %s " \
 725         "%s" \
 726         "%s" \
 727         "%s" \
 728         "%s" \
 729         TCP_LOG_COMMON_FMT
 730
 731 #define TCP_LOG_TH_FLAGS_COMMON_ARGS \
 732         outgoing ? "outgoing" : "incoming", \
 733         thflags & TH_SYN ? "SYN " : "", \
 734         thflags & TH_FIN ? "FIN " : "", \
 735         thflags & TH_RST ? "RST " : "", \
 736         thflags & TH_ACK ? "ACK " : "", \
 737         TCP_LOG_COMMON_ARGS
 738
 739 void
 740 tcp_log_th_flags(void *hdr, struct tcphdr *th, struct tcpcb *tp, bool outgoing, struct ifnet *ifp)
 741 {
 742         struct socket *so = tp->t_inpcb != NULL ? tp->t_inpcb->inp_socket : NULL;
 743         char laddr_buf[ADDRESS_STR_LEN];
 744         char faddr_buf[ADDRESS_STR_LEN];
 745         in_port_t local_port;
 746         in_port_t foreign_port;
 747         uint8_t thflags;
 748
 749         if (hdr == NULL || th == NULL) {
 750                 return;
 751         }
 752
 753         if (outgoing) {
 754                 local_port = th->th_sport;
 755                 foreign_port = th->th_dport;
 756         } else {
 757                 local_port = th->th_dport;
 758                 foreign_port = th->th_sport;
 759         }
 760         thflags = th->th_flags;
 761
 762         if ((((thflags & TH_SYN) && (tcp_log_enable_flags & TLEF_THF_SYN)) ||
 763             ((thflags & TH_FIN) && (tcp_log_enable_flags & TLEF_THF_FIN)) ||
 764             ((thflags & TH_RST) && (tcp_log_enable_flags & TLEF_THF_RST))) == false) {
 765                 return;
 766         }
 767
 768         if (ifp != NULL && tcp_log_thflags_if_family != 0 && ifp->if_family != tcp_log_thflags_if_family) {
 769                 return;
 770         }
 771
 772         if (!tcp_log_pkt_addresses(hdr, th, outgoing, laddr_buf, sizeof(laddr_buf), faddr_buf, sizeof(faddr_buf))) {
 773                 return;
 774         }
 775
 776         /* Do not log too much */
 777         if (tcp_log_is_rate_limited()) {
 778                 return;
 779         }
 780
 781         /*
 782          * When no PCB or socket just log the packet
 783          */
 784         if (tp == NULL || so == NULL) {
 785                 if (tcp_log_level_info == 0) {
 786                         os_log(OS_LOG_DEFAULT, TCP_LOG_TH_FLAGS_COMMON_FMT " no pcb",
 787                             TCP_LOG_TH_FLAGS_COMMON_ARGS);
 788                 } else {
 789                         os_log_info(OS_LOG_DEFAULT, TCP_LOG_TH_FLAGS_COMMON_FMT,
 790                             TCP_LOG_TH_FLAGS_COMMON_ARGS);
 791                 }
 792         } else {
 793 #define TCP_LOG_TH_FLAGS_PCB_FMT \
 794                 TCP_LOG_TH_FLAGS_COMMON_FMT \
 795                 "rtt: %u.%u ms " \
 796                 "rttvar: %u.%u ms " \
 797                 "syn rxmit: %u " \
 798                 "pkt rxmit: %u " \
 799                 "so_error: %d " \
 800                 "svc/tc: %u "
 801
 802 #define TCP_LOG_TH_FLAGS_PCB_ARGS \
 803             TCP_LOG_TH_FLAGS_COMMON_ARGS, \
 804             tp->t_srtt >> TCP_RTT_SHIFT, tp->t_srtt - ((tp->t_srtt >> TCP_RTT_SHIFT) << TCP_RTT_SHIFT), \
 805             tp->t_rttvar >> TCP_RTTVAR_SHIFT, tp->t_rttvar - ((tp->t_rttvar >> TCP_RTTVAR_SHIFT) << TCP_RTTVAR_SHIFT), \
 806             tp->t_stat.synrxtshift, \
 807             tp->t_stat.rxmitpkts, \
 808             so->so_error, \
 809             (so->so_flags1 & SOF1_TC_NET_SERV_TYPE) ? \
 810             so->so_netsvctype : so->so_traffic_class
 811
 812                 if (tcp_log_level_info == 0) {
 813                         os_log(OS_LOG_DEFAULT, TCP_LOG_TH_FLAGS_PCB_FMT,
 814                             TCP_LOG_TH_FLAGS_PCB_ARGS);
 815                 } else {
 816                         os_log_info(OS_LOG_DEFAULT, TCP_LOG_TH_FLAGS_PCB_FMT,
 817                             TCP_LOG_TH_FLAGS_PCB_ARGS);
 818                 }
 819 #undef TCP_LOG_TH_FLAGS_PCB_FMT
 820 #undef TCP_LOG_TH_FLAGS_PCB_ARGS
 821         }
 822 }
 823
 824 void
 825 tcp_log_drop_pkt(void *hdr, struct tcphdr *th, struct ifnet *ifp, const char *reason)
 826 {
 827         char laddr_buf[ADDRESS_STR_LEN];
 828         char faddr_buf[ADDRESS_STR_LEN];
 829         in_port_t local_port;
 830         in_port_t foreign_port;
 831         uint8_t thflags;
 832         bool outgoing = false;  /* This is only for incoming packets */
 833
 834         if (hdr == NULL || th == NULL) {
 835                 return;
 836         }
 837
 838         local_port = th->th_dport;
 839         foreign_port = th->th_sport;
 840         thflags = th->th_flags;
 841
 842         if ((((thflags & TH_SYN) && (tcp_log_enable_flags & TLEF_THF_SYN)) ||
 843             ((thflags & TH_FIN) && (tcp_log_enable_flags & TLEF_THF_FIN)) ||
 844             ((thflags & TH_RST) && (tcp_log_enable_flags & TLEF_THF_RST))) == false) {
 845                 return;
 846         }
 847
 848         if (ifp != NULL && tcp_log_thflags_if_family != 0 && ifp->if_family != tcp_log_thflags_if_family) {
 849                 return;
 850         }
 851
 852         if (!tcp_log_pkt_addresses(hdr, th, outgoing, laddr_buf, sizeof(laddr_buf), faddr_buf, sizeof(faddr_buf))) {
 853                 return;
 854         }
 855
 856         /* Do not log too much */
 857         if (tcp_log_is_rate_limited()) {
 858                 return;
 859         }
 860
 861 #define TCP_LOG_DROP_PKT_FMT \
 862             "tcp drop incoming control packet " \
 863                 TCP_LOG_TH_FLAGS_COMMON_FMT \
 864             "reason: %s"
 865
 866 #define TCP_LOG_DROP_PKT_ARGS \
 867             TCP_LOG_TH_FLAGS_COMMON_ARGS, \
 868             reason != NULL ? reason : ""
 869
 870         if (tcp_log_level_info == 0) {
 871                 os_log(OS_LOG_DEFAULT, TCP_LOG_DROP_PKT_FMT,
 872                     TCP_LOG_DROP_PKT_ARGS);
 873         } else {
 874                 os_log_info(OS_LOG_DEFAULT, TCP_LOG_DROP_PKT_FMT,
 875                     TCP_LOG_DROP_PKT_ARGS);
 876         }
 877 #undef TCP_LOG_DROP_PKT_FMT
 878 #undef TCP_LOG_DROP_PKT_ARGS
 879 }
 880
 881 void
 882 tcp_log_message(const char *func_name, int line_no, struct tcpcb *tp, const char *format, ...)
 883 {
 884         struct inpcb *inp;
 885         struct socket *so;
 886         struct ifnet *ifp;
 887         char laddr_buf[ADDRESS_STR_LEN];
 888         char faddr_buf[ADDRESS_STR_LEN];
 889         in_port_t local_port;
 890         in_port_t foreign_port;
 891         char message[256];
 892
 893         if (tp == NULL || tp->t_inpcb == NULL || tp->t_inpcb->inp_socket == NULL) {
 894                 return;
 895         }
 896
 897         /* Do not log too much */
 898         if (tcp_log_is_rate_limited()) {
 899                 return;
 900         }
 901         inp = tp->t_inpcb;
 902         so = inp->inp_socket;
 903
 904         local_port = inp->inp_lport;
 905         foreign_port = inp->inp_fport;
 906
 907         ifp = inp->inp_last_outifp != NULL ? inp->inp_last_outifp :
 908             inp->inp_boundifp != NULL ? inp->inp_boundifp : NULL;
 909
 910         tcp_log_inp_addresses(inp, laddr_buf, sizeof(laddr_buf), faddr_buf, sizeof(faddr_buf));
 911
 912         va_list ap;
 913         va_start(ap, format);
 914         vsnprintf(message, sizeof(message), format, ap);
 915         va_end(ap);
 916
 917 #define TCP_LOG_MESSAGE_FMT \
 918         "tcp (%s:%d) " \
 919         TCP_LOG_COMMON_PCB_FMT \
 920         "%s"
 921
 922 #define TCP_LOG_MESSAGE_ARGS \
 923         func_name, line_no, \
 924         TCP_LOG_COMMON_PCB_ARGS, \
 925         message
 926
 927         if (tcp_log_level_info == 0) {
 928                 os_log(OS_LOG_DEFAULT, TCP_LOG_MESSAGE_FMT,
 929                     TCP_LOG_MESSAGE_ARGS);
 930         } else {
 931                 os_log_info(OS_LOG_DEFAULT, TCP_LOG_MESSAGE_FMT,
 932                     TCP_LOG_MESSAGE_ARGS);
 933         }
 934 #undef TCP_LOG_MESSAGE_FMT
 935 #undef TCP_LOG_MESSAGE_ARGS
 936 }
 937