Add optional logging of userspace connection tracking lifecycles. Each connection logs exactly one line, written when it is purged, with its tuple, when it was created, when and why it was purged, and how long it lived.
A PMD thread must never block, format a string, or write a log line, so no part of this runs on one. The thread that already removes the connection -- the 'ct_clean' sweep thread for a normal expiry, or whichever thread handles an explicit flush -- does the formatting and the vlog write itself, inline, right there. No ring buffer, no dedicated consumer thread, and no new memory: the only addition to 'struct conn' is the 'created' timestamp, set once at creation and never touched again. A connection's removal from the table is unconditional and is never delayed by logging; a line can only ever be skipped (and counted by the 'conntrack_log_ratelimited' coverage counter), never the removal itself. Logging is disabled by default. When disabled, the cost on the datapath is a single atomic load. When enabled, output can be restricted to a list of conntrack zones and is capped at a configurable number of lines per second (default 1000, 0 for unlimited) so that a connection storm cannot flood the log; reclaiming connections continues at full speed regardless of the cap. Configure with 'ovs-appctl conntrack/log-set [enable|disable] [zones=LIST] [rate=N]' and inspect the current configuration with 'ovs-appctl conntrack/log-show'. Earlier revisions of this change used a lock-free ring buffer and a separate consumer thread to move logging work off any thread that could be a PMD. That is unnecessary here: the sweep and flush threads already touch every connection they purge, are never PMDs, and run far below packet rate, so moving the work there directly needs no new thread, no ring, and no additional memory. Tested with 'make check', including a new ofproto-dpif.at test case covering enabling, disabling, rate-limiting, and zone-filtering, and with the new 'ovstest test-conntrack benchmark-new-conns' micro-benchmark on real 25G hardware: logging disabled, or capped at the default rate, is indistinguishable from logging off for both connection creation and flush; only an explicit, non-default 'rate=0' (unlimited) measurably slows a bulk flush, trading flush time for a guarantee that no line is dropped. Signed-off-by: Thilak Raj Surendra Babu <[email protected]> Assisted-by: Claude Sonnet 5, Claude Code --- NEWS | 12 ++ lib/automake.mk | 2 + lib/conntrack-log.c | 396 ++++++++++++++++++++++++++++++++++++ lib/conntrack-log.h | 92 +++++++++ lib/conntrack-private.h | 3 + lib/conntrack.c | 25 ++- lib/dpif-netdev-unixctl.man | 19 ++ tests/ofproto-dpif.at | 70 +++++++ tests/test-conntrack.c | 124 +++++++++++ 9 files changed, 738 insertions(+), 5 deletions(-) create mode 100644 lib/conntrack-log.c create mode 100644 lib/conntrack-log.h diff --git a/NEWS b/NEWS index de1a030ad..298f883e9 100644 --- a/NEWS +++ b/NEWS @@ -1,5 +1,17 @@ Post-v4.0.0 -------------------- + - Userspace datapath: + * Added optional logging of connection tracking lifecycles. Each + connection logs exactly one line, written when it is purged, with + its tuple, when it was created and purged, and why. The line is + written inline by whichever thread already removes the connection + (the sweep thread, or whatever thread handles an explicit flush) -- + never a PMD thread, and no dedicated thread or ring buffer is added + to do it. Enable with 'ovs-appctl conntrack/log-set enable + [zones=LIST] [rate=N]'. Logging can be limited to some conntrack + zones, and output is capped at 'rate' lines per second (default + 1000) so that a connection storm cannot flood the log; connections + are still reclaimed at full speed regardless of the cap. v4.0.0 - 17 Aug 2026 diff --git a/lib/automake.mk b/lib/automake.mk index 2dfca79da..193f83592 100644 --- a/lib/automake.mk +++ b/lib/automake.mk @@ -47,6 +47,8 @@ lib_libopenvswitch_la_SOURCES = \ lib/connectivity.c \ lib/connectivity.h \ lib/conntrack-icmp.c \ + lib/conntrack-log.c \ + lib/conntrack-log.h \ lib/conntrack-private.h \ lib/conntrack-tcp.c \ lib/conntrack-tp.c \ diff --git a/lib/conntrack-log.c b/lib/conntrack-log.c new file mode 100644 index 000000000..0b998a044 --- /dev/null +++ b/lib/conntrack-log.c @@ -0,0 +1,396 @@ +/* + * Copyright (c) 2026 Nicira, Inc. + * + * Licensed under the Apache License, Version 2.0 (the "License"); + * you may not use this file except in compliance with the License. + * You may obtain a copy of the License at: + * + * http://www.apache.org/licenses/LICENSE-2.0 + * + * Unless required by applicable law or agreed to in writing, software + * distributed under the License is distributed on an "AS IS" BASIS, + * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. + * See the License for the specific language governing permissions and + * limitations under the License. + */ + +#include <config.h> + +#include "conntrack-log.h" + +#include <netinet/in.h> + +#include "coverage.h" +#include "openvswitch/dynamic-string.h" +#include "openvswitch/vlog.h" +#include "ovs-thread.h" +#include "packets.h" +#include "timeval.h" +#include "unixctl.h" +#include "util.h" + +VLOG_DEFINE_THIS_MODULE(conntrack_log); + +/* The only way a line is ever skipped: the per-second output budget is + * spent. There is no ring to overflow any more, so there is no separate + * "dropped" counter -- this one covers every skipped line. */ +COVERAGE_DEFINE(conntrack_log_ratelimited); + +atomic_bool conntrack_log_enabled_flag = false; +atomic_bool conntrack_log_all_zones = true; +atomic_uint32_t conntrack_log_zones[CT_LOG_ZONE_WORDS]; + +static atomic_uint ct_log_rate = 1000; /* Lines/sec. */ + +/* A plain per-second token bucket, shared by however many threads call + * conntrack_log_conn() -- in practice, the 'ct_clean' sweep thread almost + * always, and occasionally whatever thread handles an explicit flush. + * Neither is a PMD, both are rare and slow-moving next to a packet rate, so + * there is no dedicated lock here: a window reset racing with a budget + * decrement can let through or hold back at most one extra line right at a + * second boundary, which is not worth a mutex to avoid. */ +static atomic_llong ct_log_window_start = 0; +static atomic_int ct_log_budget = 0; + +static void ct_log_unixctl_set(struct unixctl_conn *, int, const char *[], + void *); +static void ct_log_unixctl_show(struct unixctl_conn *, int, const char *[], + void *); + +void +conntrack_log_init(void) +{ + static struct ovsthread_once once = OVSTHREAD_ONCE_INITIALIZER; + + if (ovsthread_once_start(&once)) { + unixctl_command_register("conntrack/log-set", + "[enable|disable] [zones=all|LIST] " + "[rate=N]", 0, 3, ct_log_unixctl_set, NULL); + unixctl_command_register("conntrack/log-show", "", 0, 0, + ct_log_unixctl_show, NULL); + ovsthread_once_done(&once); + } +} + +/* Returns true if a line may be written right now, having spent one unit of + * the per-second budget; false if the caller must skip it (and count it as + * rate-limited). Only ever gates whether a line is WRITTEN -- callers must + * not let it gate whether the connection is removed. */ +static bool +ct_log_take_budget(long long now) +{ + unsigned int rate; + long long window_start; + int budget_before; + + atomic_read_relaxed(&ct_log_rate, &rate); + if (!rate) { + return true; /* Unlimited. */ + } + + atomic_read_relaxed(&ct_log_window_start, &window_start); + if (now - window_start >= 1000) { + atomic_store_relaxed(&ct_log_window_start, now); + atomic_store_relaxed(&ct_log_budget, (int) rate); + } + + atomic_sub_explicit(&ct_log_budget, 1, &budget_before, + memory_order_relaxed); + return budget_before > 0; +} + +static void +ct_log_format_endpoint(struct ds *ds, const struct conn_key *key, + const struct ct_endpoint *ep) +{ + bool v6 = key->dl_type == htons(ETH_TYPE_IPV6); + + if (v6) { + ds_put_char(ds, '['); + ipv6_format_addr(&ep->addr.ipv6, ds); + ds_put_char(ds, ']'); + } else { + ds_put_format(ds, IP_FMT, IP_ARGS(ep->addr.ipv4)); + } + + if (key->nw_proto == IPPROTO_ICMP || key->nw_proto == IPPROTO_ICMPV6) { + ds_put_format(ds, "(id=%"PRIu16",type=%"PRIu8",code=%"PRIu8")", + ntohs(ep->icmp_id), ep->icmp_type, ep->icmp_code); + } else { + ds_put_format(ds, ":%"PRIu16, ntohs(ep->port)); + } +} + +static void +ct_log_format_tuple(struct ds *ds, const char *name, + const struct conn_key *key) +{ + ds_put_format(ds, " %s=", name); + ct_log_format_endpoint(ds, key, &key->src); + ds_put_cstr(ds, "->"); + ct_log_format_endpoint(ds, key, &key->dst); +} + +static const char * +ct_log_reason_name(enum ct_log_reason reason) +{ + switch (reason) { + case CT_LOG_R_EXPIRED: + return "expired"; + case CT_LOG_R_FLUSHED: + return "flushed"; + case CT_LOG_R_SHUTDOWN: + default: + return "unknown"; + } +} + +/* Logs 'conn's whole lifecycle -- creation and purge -- in one line. See + * the comment on conntrack_log_conn() in conntrack-log.h: this runs inline, + * on whichever thread is already removing 'conn', with no ring and no + * separate consumer thread. */ +void +conntrack_log_conn(enum ct_log_reason reason, struct conn *conn) +{ + const struct conn_key *orig = &conn->key_node[CT_DIR_FWD].key; + const struct conn_key *reply = &conn->key_node[CT_DIR_REV].key; + long long purged_wall, age_ms, created_wall; + uint32_t mark; + struct ds ds; + + if (!ct_log_take_budget(time_msec())) { + COVERAGE_INC(conntrack_log_ratelimited); + return; + } + + /* 'created' is in time_msec() (monotonic) units, immune to wall-clock + * adjustments; reconstruct a wall-clock creation time from the current + * wall time and that monotonic age, the same way a human-readable + * 'created' timestamp would be computed anywhere else in this file. */ + age_ms = time_msec() - conn->created; + purged_wall = time_wall_msec(); + created_wall = purged_wall - age_ms; + + ovs_mutex_lock(&conn->lock); + mark = conn->mark; + ovs_mutex_unlock(&conn->lock); + + ds_init(&ds); + ds_put_cstr(&ds, "CT"); + + switch (orig->nw_proto) { + case IPPROTO_TCP: + ds_put_cstr(&ds, " proto=tcp"); + break; + case IPPROTO_UDP: + ds_put_cstr(&ds, " proto=udp"); + break; + case IPPROTO_ICMP: + ds_put_cstr(&ds, " proto=icmp"); + break; + case IPPROTO_ICMPV6: + ds_put_cstr(&ds, " proto=icmpv6"); + break; + default: + ds_put_format(&ds, " proto=%"PRIu8, orig->nw_proto); + } + ds_put_format(&ds, " zone=%"PRIu16, orig->zone); + ct_log_format_tuple(&ds, "orig", orig); + ct_log_format_tuple(&ds, "reply", reply); + + if (conn->nat_action) { + ds_put_format(&ds, " nat=%s%s%s", + conn->nat_action & NAT_ACTION_SNAT_ALL ? "snat" : "", + (conn->nat_action & NAT_ACTION_SNAT_ALL) + && (conn->nat_action & NAT_ACTION_DNAT_ALL) ? "," : "", + conn->nat_action & NAT_ACTION_DNAT_ALL ? "dnat" : ""); + } + if (mark) { + ds_put_format(&ds, " mark=%#"PRIx32, mark); + } + ds_put_cstr(&ds, " created="); + ds_put_strftime_msec(&ds, "%Y-%m-%dT%H:%M:%S.###Z", created_wall, true); + ds_put_cstr(&ds, " purged="); + ds_put_strftime_msec(&ds, "%Y-%m-%dT%H:%M:%S.###Z", purged_wall, true); + ds_put_format(&ds, " age=%lldms reason=%s", + age_ms, ct_log_reason_name(reason)); + + VLOG_INFO("%s", ds_cstr(&ds)); + ds_destroy(&ds); +} + +static bool +ct_log_parse_zones(const char *spec, uint32_t words[CT_LOG_ZONE_WORDS], + bool *all) +{ + char *copy = xstrdup(spec), *save = NULL, *tok; + bool ok = true; + + *all = false; + memset(words, 0, CT_LOG_ZONE_WORDS * sizeof *words); + for (tok = strtok_r(copy, ",", &save); tok && ok; + tok = strtok_r(NULL, ",", &save)) { + unsigned int lo, hi; + int n; + + if (!strcmp(tok, "all")) { + *all = true; + } else if (ovs_scan(tok, "%u-%u%n", &lo, &hi, &n) && !tok[n] + && lo <= hi && hi <= UINT16_MAX) { + for (unsigned int z = lo; z <= hi; z++) { + words[z / 32] |= UINT32_C(1) << (z % 32); + } + } else if (str_to_uint(tok, 10, &lo) && lo <= UINT16_MAX) { + words[lo / 32] |= UINT32_C(1) << (lo % 32); + } else { + ok = false; + } + } + free(copy); + return ok; +} + +static void +ct_log_set_zones(const uint32_t words[CT_LOG_ZONE_WORDS], bool all) +{ + /* Write the bitmap before dropping "all", and raise "all" first, so that + * a concurrent reader never sees a filter that is neither the old nor + * the new one for a zone that is in both. */ + if (all) { + atomic_store_relaxed(&conntrack_log_all_zones, true); + return; + } + for (int i = 0; i < CT_LOG_ZONE_WORDS; i++) { + atomic_store_relaxed(&conntrack_log_zones[i], words[i]); + } + atomic_store_explicit(&conntrack_log_all_zones, false, + memory_order_release); +} + +static void +ct_log_format_zones(struct ds *ds) +{ + bool all; + int start = -1; + + atomic_read_relaxed(&conntrack_log_all_zones, &all); + if (all) { + ds_put_cstr(ds, "all"); + return; + } + + for (int z = 0; z <= UINT16_MAX + 1; z++) { + bool set = false; + + if (z <= UINT16_MAX) { + uint32_t word; + + atomic_read_relaxed(&conntrack_log_zones[z / 32], &word); + set = word & (UINT32_C(1) << (z % 32)); + } + if (set && start < 0) { + start = z; + } else if (!set && start >= 0) { + ds_put_format(ds, "%s%d", ds->length && ds_last(ds) != ' ' + ? "," : "", start); + if (z - 1 != start) { + ds_put_format(ds, "-%d", z - 1); + } + start = -1; + } + } + if (ds_last(ds) == ' ') { + ds_put_cstr(ds, "none"); + } +} + +void +conntrack_log_set(bool enable, unsigned int rate) +{ + atomic_store_relaxed(&ct_log_rate, rate); + /* Release: pairs with the acquire in conntrack_log_enabled(), so a + * reader that sees 'enabled' also sees a consistent zone filter. */ + atomic_store_explicit(&conntrack_log_enabled_flag, enable, + memory_order_release); +} + +static void +ct_log_unixctl_set(struct unixctl_conn *conn, int argc, const char *argv[], + void *aux OVS_UNUSED) +{ + bool new_enabled, have_enabled = false, have_rate = false; + bool have_zones = false, all_zones = false; + unsigned int rate = 0; + uint32_t *zone_words = NULL; + + for (int i = 1; i < argc; i++) { + if (!strcmp(argv[i], "enable")) { + new_enabled = true; + have_enabled = true; + } else if (!strcmp(argv[i], "disable")) { + new_enabled = false; + have_enabled = true; + } else if (!strncmp(argv[i], "rate=", 5)) { + if (!str_to_uint(argv[i] + 5, 10, &rate)) { + free(zone_words); + unixctl_command_reply_error(conn, "invalid rate"); + return; + } + have_rate = true; + } else if (!strncmp(argv[i], "zones=", 6)) { + if (!zone_words) { + zone_words = xmalloc(CT_LOG_ZONE_WORDS * sizeof *zone_words); + } + if (!ct_log_parse_zones(argv[i] + 6, zone_words, &all_zones)) { + free(zone_words); + unixctl_command_reply_error(conn, "invalid zones list"); + return; + } + have_zones = true; + } else { + free(zone_words); + unixctl_command_reply_error(conn, "unknown argument"); + return; + } + } + + if (have_zones) { + ct_log_set_zones(zone_words, all_zones); + } + free(zone_words); + + if (have_rate) { + atomic_store_relaxed(&ct_log_rate, rate); + } + if (have_enabled) { + bool cur_enabled; + + atomic_read_relaxed(&conntrack_log_enabled_flag, &cur_enabled); + if (new_enabled != cur_enabled) { + atomic_store_explicit(&conntrack_log_enabled_flag, new_enabled, + memory_order_release); + } + } + unixctl_command_reply(conn, NULL); +} + +static void +ct_log_unixctl_show(struct unixctl_conn *conn, int argc OVS_UNUSED, + const char *argv[] OVS_UNUSED, void *aux OVS_UNUSED) +{ + struct ds ds = DS_EMPTY_INITIALIZER; + bool enabled; + unsigned int rate; + + atomic_read_relaxed(&conntrack_log_enabled_flag, &enabled); + atomic_read_relaxed(&ct_log_rate, &rate); + + ds_put_format(&ds, "logging: %s\n", enabled ? "enabled" : "disabled"); + ds_put_cstr(&ds, "zones: "); + ct_log_format_zones(&ds); + ds_put_char(&ds, '\n'); + ds_put_format(&ds, "rate limit: %u lines/sec%s\n", rate, + rate ? "" : " (unlimited)"); + unixctl_command_reply(conn, ds_cstr(&ds)); + ds_destroy(&ds); +} diff --git a/lib/conntrack-log.h b/lib/conntrack-log.h new file mode 100644 index 000000000..3c5372b54 --- /dev/null +++ b/lib/conntrack-log.h @@ -0,0 +1,92 @@ +/* + * Copyright (c) 2026 Nicira, Inc. + * + * Licensed under the Apache License, Version 2.0 (the "License"); + * you may not use this file except in compliance with the License. + * You may obtain a copy of the License at: + * + * http://www.apache.org/licenses/LICENSE-2.0 + * + * Unless required by applicable law or agreed to in writing, software + * distributed under the License is distributed on an "AS IS" BASIS, + * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. + * See the License for the specific language governing permissions and + * limitations under the License. + */ + +#ifndef CONNTRACK_LOG_H +#define CONNTRACK_LOG_H 1 + +#include <stdbool.h> +#include <stdint.h> + +#include "conntrack-private.h" +#include "ovs-atomic.h" + +/* Connection tracking event logging. + * + * A connection's whole lifecycle is reported in a single line, written when + * the connection is purged: by the existing 'ct_clean' sweep thread for a + * normal expiry, or by whichever thread handles an explicit flush. Neither + * of those is ever a PMD thread, so the formatting and the vlog write happen + * inline, right there -- no dedicated thread, no ring buffer, no additional + * memory. The only state this adds is the 'created' timestamp already + * carried on struct conn. + * + * When logging is disabled, the cost on the datapath is one atomic load + * (see conntrack_log_enabled()), and nothing is logged until a connection + * that is already being torn down reaches conn_clean(). */ + +enum ct_log_reason { + CT_LOG_R_EXPIRED, /* Timed out, or replaced by a new connection. */ + CT_LOG_R_FLUSHED, /* Removed by an explicit flush. */ + CT_LOG_R_SHUTDOWN, /* Connection tracker destroyed; never logged. */ +}; + +#define CT_LOG_ZONE_WORDS ((UINT16_MAX + 1) / 32) + +extern atomic_bool conntrack_log_enabled_flag; +extern atomic_bool conntrack_log_all_zones; +extern atomic_uint32_t conntrack_log_zones[CT_LOG_ZONE_WORDS]; + +void conntrack_log_init(void); + +/* Turns logging on or off, and sets the maximum rate in lines per second + * (0 for unlimited). */ +void conntrack_log_set(bool enable, unsigned int rate); + +/* Returns true if logging is enabled for connections in conntrack zone + * 'zone'. The zone filter is only looked at once logging is enabled, so the + * cost when it is disabled is one atomic load. */ +static inline bool +conntrack_log_enabled(uint16_t zone) +{ + bool enabled, all_zones; + + atomic_read_explicit(&conntrack_log_enabled_flag, &enabled, + memory_order_acquire); + if (OVS_LIKELY(!enabled)) { + return false; + } + + atomic_read_relaxed(&conntrack_log_all_zones, &all_zones); + if (all_zones) { + return true; + } else { + uint32_t word; + + atomic_read_relaxed(&conntrack_log_zones[zone / 32], &word); + return word & (UINT32_C(1) << (zone % 32)); + } +} + +/* Logs 'conn's lifecycle in one line: its tuple, how long it lived, and why + * it was purged. Called inline by whichever thread is already removing + * 'conn' -- never a PMD. Callers must check conntrack_log_enabled() first, + * so the (small) cost of reading the connection is only paid when logging is + * on; removal of 'conn' itself must already be unconditional and must never + * be made to wait on this call, which may itself skip writing a line (and + * count it as rate-limited) without affecting that removal at all. */ +void conntrack_log_conn(enum ct_log_reason, struct conn *); + +#endif /* conntrack-log.h */ diff --git a/lib/conntrack-private.h b/lib/conntrack-private.h index f1132e8aa..154b9794e 100644 --- a/lib/conntrack-private.h +++ b/lib/conntrack-private.h @@ -156,6 +156,9 @@ struct conn { bool alg_related; /* True if alg data connection. */ uint32_t tp_id; /* Timeout policy ID. */ + + long long created; /* Creation time, in 'time_msec()' units. Immutable + * once the connection is inserted. */ }; enum ct_update_res { diff --git a/lib/conntrack.c b/lib/conntrack.c index f84cdd216..25dd4b586 100644 --- a/lib/conntrack.c +++ b/lib/conntrack.c @@ -23,6 +23,7 @@ #include <string.h> #include "conntrack.h" +#include "conntrack-log.h" #include "conntrack-private.h" #include "conntrack-tp.h" #include "coverage.h" @@ -253,6 +254,7 @@ conntrack_init(void) * set it first to ensure it is available. */ ct->hash_basis = random_uint32(); + conntrack_log_init(); ovs_rwlock_init(&ct->resources_lock); ovs_rwlock_wrlock(&ct->resources_lock); @@ -581,13 +583,25 @@ conn_clean__(struct conntrack *ct, struct conn *conn) /* Also removes the associated nat 'conn' from the lookup datastructures. */ static void -conn_clean(struct conntrack *ct, struct conn *conn) +conn_clean(struct conntrack *ct, struct conn *conn, + enum ct_log_reason reason) OVS_EXCLUDED(conn->lock, ct->ct_lock) { if (atomic_flag_test_and_set(&conn->reclaimed)) { return; } + /* Logging (if enabled) happens inline, here, on whichever thread is + * already doing the removal below -- the 'ct_clean' sweep thread for a + * normal expiry, or whatever thread issued an explicit flush. Neither + * is ever a PMD. Removal itself is unconditional and must not be made + * to wait on it; a skipped line (because the output rate is capped) + * never affects whether the connection is reclaimed. */ + if (reason != CT_LOG_R_SHUTDOWN + && conntrack_log_enabled(conn->key_node[CT_DIR_FWD].key.zone)) { + conntrack_log_conn(reason, conn); + } + ovs_mutex_lock(&ct->ct_lock); conn_clean__(ct, conn); ovs_mutex_unlock(&ct->ct_lock); @@ -621,7 +635,7 @@ conntrack_destroy(struct conntrack *ct) for (unsigned i = 0; i < N_EXP_LISTS; i++) { RCULIST_FOR_EACH (conn, node, &ct->exp_lists[i]) { - conn_clean(ct, conn); + conn_clean(ct, conn, CT_LOG_R_SHUTDOWN); } } @@ -1064,6 +1078,7 @@ conn_not_found(struct conntrack *ct, struct dp_packet *pkt, } nc = new_conn(ct, pkt, &ctx->key, now, tp_id); + nc->created = now; fwd_key_node = &nc->key_node[CT_DIR_FWD]; rev_key_node = &nc->key_node[CT_DIR_REV]; memcpy(&fwd_key_node->key, &ctx->key, sizeof fwd_key_node->key); @@ -1597,7 +1612,7 @@ ct_sweep(struct conntrack *ct, struct rculist *list, long long now, RCULIST_FOR_EACH (conn, node, list) { if (conn_expired(conn, now)) { - conn_clean(ct, conn); + conn_clean(ct, conn, CT_LOG_R_EXPIRED); cleaned++; } @@ -2991,7 +3006,7 @@ conntrack_flush_zone(struct conntrack *ct, const uint16_t zone) continue; } conn = CONTAINER_OF(keyn, struct conn, key_node[CT_DIR_FWD]); - conn_clean(ct, conn); + conn_clean(ct, conn, CT_LOG_R_FLUSHED); } return 0; @@ -3024,7 +3039,7 @@ conntrack_flush_tuple(struct conntrack *ct, const struct ct_dpif_tuple *tuple, conn_lookup(ct, &key, time_msec(), &conn, NULL); if (conn) { - conn_clean(ct, conn); + conn_clean(ct, conn, CT_LOG_R_FLUSHED); } else { VLOG_WARN("Tuple not found"); error = ENOENT; diff --git a/lib/dpif-netdev-unixctl.man b/lib/dpif-netdev-unixctl.man index 2fb2c5442..91aea9222 100644 --- a/lib/dpif-netdev-unixctl.man +++ b/lib/dpif-netdev-unixctl.man @@ -228,3 +228,22 @@ recirculation (only in balance-tcp mode). When this is the case, the above command prints the load-balancing information of the bonds configured in datapath \fIdp\fR showing the interface associated with each bucket (hash). +. +.IP "\fBconntrack/log-set\fR [\fBenable\fR | \fBdisable\fR] [\fBzones=\fIlist\fR] [\fBrate=\fIN\fR]" +Configures logging of userspace connection tracking lifecycles (disabled by +default). Each connection logs exactly one line, written when it is purged, +carrying its tuple, when it was created and purged, how long it lived, and +why it was removed. \fBzones\fR limits logging to connections in the given +conntrack zones, as a comma-separated list of zone numbers and ranges such as +\fB1,5,10\-20\fR, or \fBall\fR (the default). The line is written inline, by +whichever thread is already removing the connection (the sweep thread for a +normal expiry, or whatever thread handles an explicit flush) under the +\fBconntrack_log\fR vlog module at \fBinfo\fR level; removal of the +connection itself is unconditional and is never delayed by this. If more +than \fIN\fR lines per second (default 1000, 0 for unlimited) would be +written, the excess is skipped and counted by the +\fBconntrack_log_ratelimited\fR coverage counter, so that a connection storm +cannot flood the log. +. +.IP "\fBconntrack/log-show\fR" +Prints the current connection tracking logging configuration. diff --git a/tests/ofproto-dpif.at b/tests/ofproto-dpif.at index efb36e058..8c582b1bd 100644 --- a/tests/ofproto-dpif.at +++ b/tests/ofproto-dpif.at @@ -12293,6 +12293,76 @@ udp,orig=(src=10.1.1.2,dst=10.1.1.1,sport=4,dport=3),reply=(src=10.1.1.1,dst=10. OVS_VSWITCHD_STOP AT_CLEANUP +AT_SETUP([ofproto-dpif - conntrack - event logging]) +OVS_VSWITCHD_START + +add_of_ports br0 1 2 + +AT_DATA([flows.txt], [dnl +table=0,priority=100,arp,action=normal +table=0,priority=10,udp,action=ct(commit,zone=5,table=1) +table=0,priority=20,udp,tp_src=7,action=ct(commit,zone=6,table=1) +table=0,priority=1,action=drop +table=1,priority=10,ct_state=+trk+new,action=2 +]) +AT_CHECK([ovs-ofctl add-flows br0 flows.txt]) + +AT_CHECK([ovs-appctl conntrack/log-show], [0], [dnl +logging: disabled +zones: all +rate limit: 1000 lines/sec +]) + +dnl Nothing is logged while disabled. +AT_CHECK([ovs-appctl netdev-dummy/receive p1 'in_port(1),eth(src=50:54:00:00:00:09,dst=50:54:00:00:00:0a),eth_type(0x0800),ipv4(src=10.1.1.1,dst=10.1.1.2,proto=17,tos=0,ttl=64,frag=no),udp(src=1,dst=2)']) +OVS_WAIT_UNTIL([ovs-appctl dpctl/dump-conntrack | grep -q 'zone=5']) +AT_CHECK([ovs-appctl dpctl/flush-conntrack]) +AT_CHECK([ovs-appctl conntrack/log-set bogus], [2], [], [ignore]) + +AT_CHECK([ovs-appctl conntrack/log-set enable rate=100]) +AT_CHECK([ovs-appctl conntrack/log-show], [0], [dnl +logging: enabled +zones: all +rate limit: 100 lines/sec +]) + +dnl A single line, carrying both the creation and the purge, is written +dnl when the connection is flushed -- nothing is logged at creation time. +AT_CHECK([ovs-appctl netdev-dummy/receive p1 'in_port(1),eth(src=50:54:00:00:00:09,dst=50:54:00:00:00:0a),eth_type(0x0800),ipv4(src=10.1.1.1,dst=10.1.1.2,proto=17,tos=0,ttl=64,frag=no),udp(src=3,dst=4)']) +OVS_WAIT_UNTIL([ovs-appctl dpctl/dump-conntrack | grep -q 'zone=5']) +AT_CHECK([grep -c '|conntrack_log' ovs-vswitchd.log], [1], [0 +]) +AT_CHECK([ovs-appctl dpctl/flush-conntrack]) +OVS_WAIT_UNTIL([grep -q 'CT proto=udp' ovs-vswitchd.log]) + +AT_CHECK([grep '|conntrack_log' ovs-vswitchd.log | sed 's/.*|INFO|//; s/created=[[0-9-]]*T[[0-9:.]]*Z/created=C/; s/purged=[[0-9-]]*T[[0-9:.]]*Z/purged=P/; s/age=[[0-9]]*ms/age=Ams/'], [0], [dnl +CT proto=udp zone=5 orig=10.1.1.1:3->10.1.1.2:4 reply=10.1.1.2:4->10.1.1.1:3 created=C purged=P age=Ams reason=flushed +]) + +dnl Restrict logging to some zones. +AT_CHECK([ovs-appctl conntrack/log-set zones=6,10-12]) +AT_CHECK([ovs-appctl conntrack/log-show], [0], [dnl +logging: enabled +zones: 6,10-12 +rate limit: 100 lines/sec +]) +AT_CHECK([ovs-appctl conntrack/log-set zones=70000], [2], [], [ignore]) +AT_CHECK([ovs-appctl conntrack/log-set zones=9-3], [2], [], [ignore]) + +AT_CHECK([ovs-appctl netdev-dummy/receive p1 'in_port(1),eth(src=50:54:00:00:00:09,dst=50:54:00:00:00:0a),eth_type(0x0800),ipv4(src=10.1.1.1,dst=10.1.1.2,proto=17,tos=0,ttl=64,frag=no),udp(src=5,dst=6)']) +AT_CHECK([ovs-appctl netdev-dummy/receive p1 'in_port(1),eth(src=50:54:00:00:00:09,dst=50:54:00:00:00:0a),eth_type(0x0800),ipv4(src=10.1.1.1,dst=10.1.1.2,proto=17,tos=0,ttl=64,frag=no),udp(src=7,dst=8)']) +AT_CHECK([ovs-appctl dpctl/flush-conntrack]) +OVS_WAIT_UNTIL([grep -q 'CT proto=udp zone=6 ' ovs-vswitchd.log]) +dnl The zone-5 connection (tp_src=5) was purged too, but zone 5 is now +dnl filtered out: its line, distinguished by its source port, never appears +dnl (the zone=5 line already in the log above is from an earlier connection, +dnl logged before the filter was narrowed). +AT_CHECK([grep -c '10.1.1.1:5->' ovs-vswitchd.log], [1], [0 +]) + +OVS_VSWITCHD_STOP +AT_CLEANUP + AT_SETUP([ofproto-dpif - conntrack - related nat]) OVS_VSWITCHD_START diff --git a/tests/test-conntrack.c b/tests/test-conntrack.c index 2babe989c..d224cf04c 100644 --- a/tests/test-conntrack.c +++ b/tests/test-conntrack.c @@ -16,11 +16,13 @@ #include <config.h> #include "conntrack.h" +#include "conntrack-log.h" #include "dp-packet.h" #include "fatal-signal.h" #include "flow.h" #include "netdev.h" +#include "openvswitch/vlog.h" #include "ovs-thread.h" #include "ovstest.h" #include "pcap-file.h" @@ -260,6 +262,124 @@ test_benchmark(struct ovs_cmdl_context *ctx) free(threads); } +static long long +now_usec(void) +{ + struct timespec ts; + + clock_gettime(CLOCK_MONOTONIC, &ts); + return ts.tv_sec * 1000000LL + ts.tv_nsec / 1000; +} + +static void * +new_conns_thread_main(void *aux_) +{ + struct thread_aux *aux = aux_; + size_t n_batches = (n_pkts + batch_size - 1) / batch_size; + struct dp_packet_batch **batches = xzalloc(n_batches * sizeof *batches); + long long now = time_msec(); + struct dp_packet *pkt; + ovs_be16 dl_type = 0; + size_t i, conn = 0; + + for (i = 0; i < n_batches; i++) { + batches[i] = xzalloc(sizeof *batches[i]); + dp_packet_batch_init(batches[i]); + for (size_t j = 0; j < batch_size && conn < n_pkts; j++, conn++) { + dp_packet_batch_add(batches[i], + build_packet(1 + conn, 2 + aux->tid, + &dl_type)); + } + } + + ovs_barrier_block(&barrier); + for (i = 0; i < n_batches; i++) { + conntrack_execute(ct, batches[i], dl_type, false, true, 0, NULL, NULL, + NULL, NULL, now, 0); + } + ovs_barrier_block(&barrier); + + for (i = 0; i < n_batches; i++) { + DP_PACKET_BATCH_FOR_EACH (j, pkt, batches[i]) { + pkt_metadata_init_conn(&pkt->md); + } + destroy_packets(batches[i]); + } + free(batches); + return NULL; +} + +/* Benchmark of new connection creation and destruction. Each of 'n_threads' + * threads commits 'n_conns' distinct UDP connections, 'NETDEV_MAX_BURST' per + * call. Then all the connections are flushed. 'mode' is "off" or "on" and + * selects whether connection tracking logging is enabled; when it is, every + * connection logs exactly one combined creation-and-purge line, written + * inline by the thread that flushes it. */ +static void +test_benchmark_new_conns(struct ovs_cmdl_context *ctx) +{ + struct thread_aux *threads; + long long start, create_us, flush_us; + bool enabled; + unsigned i; + + fatal_signal_init(); + + n_threads = strtoul(ctx->argv[1], NULL, 0); + n_pkts = strtoul(ctx->argv[2], NULL, 0); + if (!n_threads || !n_pkts || n_pkts > 60000) { + ovs_fatal(0, "n_threads >= 1 and 1 <= n_conns <= 60000"); + } + batch_size = NETDEV_MAX_BURST; + if (!strcmp(ctx->argv[3], "on")) { + enabled = true; + } else if (!strcmp(ctx->argv[3], "off")) { + enabled = false; + } else { + ovs_fatal(0, "mode must be off or on"); + } + + unsigned int rate = ctx->argc > 5 ? strtoul(ctx->argv[5], NULL, 0) : 0; + + /* Keep the log output out of the terminal. */ + vlog_set_levels(NULL, VLF_CONSOLE, VLL_OFF); + vlog_set_log_file(ctx->argc > 4 ? ctx->argv[4] : "/dev/null"); + + threads = xcalloc(n_threads, sizeof *threads); + ovs_barrier_init(&barrier, n_threads + 1); + ct = conntrack_init(); + conntrack_log_set(enabled, rate); + + for (i = 0; i < n_threads; i++) { + threads[i].tid = i; + threads[i].thread = ovs_thread_create("ct_thread", + new_conns_thread_main, + &threads[i]); + } + ovs_barrier_block(&barrier); + start = now_usec(); + ovs_barrier_block(&barrier); + create_us = now_usec() - start; + + for (i = 0; i < n_threads; i++) { + xpthread_join(threads[i].thread, NULL); + } + + start = now_usec(); + conntrack_flush(ct, NULL); + flush_us = now_usec() - start; + + printf("mode=%-4s threads=%2lu conns/thread=%lu create: %6lld us " + "(%5.0f ns/conn/thread) flush: %6lld us\n", + ctx->argv[3], n_threads, n_pkts, create_us, + create_us * 1e3 / n_pkts, flush_us); + + conntrack_log_set(false, 0); + conntrack_destroy(ct); + ovs_barrier_destroy(&barrier); + free(threads); +} + static void test_benchmark_zones(struct ovs_cmdl_context *ctx) { @@ -589,6 +709,10 @@ static const struct ovs_cmdl_command commands[] = { * 'batch_size' (1 by default) per call, with the commit flag set. * Prints the ct_state of each packet. */ {"pcap", "file [batch_size]", 1, 2, test_pcap, OVS_RO}, + /* Measures new connection creation (with optional event logging) and + * flush time. */ + {"benchmark-new-conns", "n_threads n_conns off|on [logfile] [rate]", 3, 5, + test_benchmark_new_conns, OVS_RO}, /* Creates 'n_conns' connections in 'n_zones' zones each. * Afterwards triggers flush requests repeadeatly for the last filled zone * and an empty zone. */ -- 2.43.0 _______________________________________________ dev mailing list [email protected] https://mail.openvswitch.org/mailman/listinfo/ovs-dev
