[RFC PATCH v2] net: track raw dev_put()/dev_hold() usage under CONFIG_NET_DEV_REFCNT_TRACKER=y
Tetsuo Handa <[email protected]>
| Newsgroups | org.kernel.vger.netdev |
|---|---|
| Message-ID | <[email protected]> |
syzbot is still reporting
unregister_netdevice: waiting for DEV to become free
problems. There is netdevice_tracker which helps identifying culprit
module, but one of barriers is that not all existing callers are using
netdevice_tracker and nobody is willing to convert existing callers to use
netdevice_tracker. Recently, AI system is acquiring ability to analyze
imbalance of raw dev_put()/dev_hold() usage (i.e. without converting to
netdevice_tracker), as long as we succeed to dump all dev_put()/dev_hold()
usage [1].
This patch introduces buffer for tracking raw dev_put()/dev_hold() usage.
This mechanism helped fixing 10 bugs using linux-next tree [2]. However,
since remaining bugs are no longer easily reproducible in linux-next tree,
I want to make this mechanism available in networking trees.
This patch also introduces NETDEV_DEBUG_UNREGISTER event which is fired
when "unregister_netdevice: waiting for DEV to become free" is emitted.
This event offers ability to execute custom debug code only when
NETDEV_UNREGISTER event is failing to drop refcount. The "#syz test"
command cannot be used without a reliable reproducer (and remaining bugs
are difficult to reproduce), but the ability to execute custom debug code
conpensates for lack of a reliable reproducer because it allows us to test
whether doing something after the kernel concluded that unregistration got
stuck makes differences. For example, commit 4efa91a28576 ("xfrm: always
flush state and policy upon NETDEV_UNREGISTER event") was made because
I succeeded to confirm that executing xfrm_dev_unregister() upon
NETDEV_DEBUG_UNREGISTER event made difference [3]. NETDEV_DEBUG_UNREGISTER
event has been also used for emitting debug messages and doing some actions
when debugging this problem in e.g. net/can/j1939 and drivers/infiniband
modules.
Since dumping all dev_put()/dev_hold() usage of a netdev which is stuck
at NETDEV_UNREGISTER event might emit 100+ call traces, it is important
to reduce amount of printk() messages in order to increase likeliness of
syzbot successfully capturing all dev_put()/dev_hold() usage. To reduce
amount of printk() messages, several functions are explicitly marked as
"noinline", and a filter function tries to reduce common part of traces.
Link: https://lkml.kernel.org/r/[email protected] [1]
Link: https://syzkaller.appspot.com/bug?extid=881d65229ca4f9ae8c84 [2]
Link: https://git.kernel.org/pub/scm/linux/kernel/git/next/linux-next.git/commit?id=fc0f090e41e652d158f946c616cdd82baed3c8f4 [3]
Signed-off-by: Tetsuo Handa <[email protected]>
---
Changes in v2:
- Addressed sashiko's review comments at
https://sashiko.dev/#/patchset/bd87fb25-b125-42b6-b70f-5bc5a9b6bcbd%40I-love.SAKURA.ne.jp .
include/linux/netdevice.h | 14 ++
kernel/softirq.c | 4 +
kernel/workqueue.c | 4 +
net/core/dev.c | 266 ++++++++++++++++++++++++++++++++++++++
net/core/lock_debug.c | 1 +
net/socket.c | 32 ++++-
6 files changed, 314 insertions(+), 7 deletions(-)
diff --git a/include/linux/netdevice.h b/include/linux/netdevice.h
index 8840b126979f..12dc2c1dc031 100644
--- a/include/linux/netdevice.h
+++ b/include/linux/netdevice.h
@@ -2144,6 +2144,8 @@ enum netdev_reg_state {
*
* FIXME: cleanup struct net_device such that network protocol info
* moves out.
+ *
+ * @netdev_trace_buffer_list: Linked list for debugging refcount leak.
*/
struct net_device {
@@ -2300,6 +2302,9 @@ struct net_device {
#if IS_ENABLED(CONFIG_TLS_DEVICE)
const struct tlsdev_ops *tlsdev_ops;
#endif
+#if defined(CONFIG_NET_DEV_REFCNT_TRACKER) && defined(CONFIG_KALLSYMS)
+ struct list_head netdev_trace_buffer_list;
+#endif
unsigned int operstate;
unsigned char link_mode;
@@ -3250,6 +3255,7 @@ enum netdev_cmd {
NETDEV_OFFLOAD_XSTATS_REPORT_USED,
NETDEV_OFFLOAD_XSTATS_REPORT_DELTA,
NETDEV_XDP_FEAT_CHANGE,
+ NETDEV_DEBUG_UNREGISTER,
};
const char *netdev_cmd_to_name(enum netdev_cmd cmd);
@@ -4466,9 +4472,16 @@ static inline bool dev_nit_active(const struct net_device *dev)
void dev_queue_xmit_nit(struct sk_buff *skb, struct net_device *dev);
+#if defined(CONFIG_NET_DEV_REFCNT_TRACKER) && defined(CONFIG_KALLSYMS)
+void save_netdev_trace_buffer(struct net_device *dev, int delta);
+#else
+static inline void save_netdev_trace_buffer(struct net_device *dev, int delta) { }
+#endif
+
static inline void __dev_put(struct net_device *dev)
{
if (dev) {
+ save_netdev_trace_buffer(dev, -1);
#ifdef CONFIG_PCPU_DEV_REFCNT
this_cpu_dec(*dev->pcpu_refcnt);
#else
@@ -4480,6 +4493,7 @@ static inline void __dev_put(struct net_device *dev)
static inline void __dev_hold(struct net_device *dev)
{
if (dev) {
+ save_netdev_trace_buffer(dev, 1);
#ifdef CONFIG_PCPU_DEV_REFCNT
this_cpu_inc(*dev->pcpu_refcnt);
#else
diff --git a/kernel/softirq.c b/kernel/softirq.c
index 4425d8dce44b..c5c194bec36e 100644
--- a/kernel/softirq.c
+++ b/kernel/softirq.c
@@ -576,6 +576,10 @@ static inline bool lockdep_softirq_start(void) { return false; }
static inline void lockdep_softirq_end(bool in_hardirq) { }
#endif
+#if defined(CONFIG_NET_DEV_REFCNT_TRACKER) && defined(CONFIG_KALLSYMS)
+static noinline void handle_softirqs(bool ksirqd);
+#endif
+
static void handle_softirqs(bool ksirqd)
{
unsigned long end = jiffies + MAX_SOFTIRQ_TIME;
diff --git a/kernel/workqueue.c b/kernel/workqueue.c
index 78068ae8f28a..d761268686f2 100644
--- a/kernel/workqueue.c
+++ b/kernel/workqueue.c
@@ -3203,6 +3203,10 @@ static bool manage_workers(struct worker *worker)
return true;
}
+#if defined(CONFIG_NET_DEV_REFCNT_TRACKER) && defined(CONFIG_KALLSYMS)
+static noinline void process_one_work(struct worker *worker, struct work_struct *work);
+#endif
+
/**
* process_one_work - process single work
* @worker: self
diff --git a/net/core/dev.c b/net/core/dev.c
index af260ff5462a..86fdaa096aed 100644
--- a/net/core/dev.c
+++ b/net/core/dev.c
@@ -1875,6 +1875,7 @@ const char *netdev_cmd_to_name(enum netdev_cmd cmd)
N(PRE_CHANGEADDR) N(OFFLOAD_XSTATS_ENABLE) N(OFFLOAD_XSTATS_DISABLE)
N(OFFLOAD_XSTATS_REPORT_USED) N(OFFLOAD_XSTATS_REPORT_DELTA)
N(XDP_FEAT_CHANGE)
+ N(DEBUG_UNREGISTER)
}
#undef N
return "UNKNOWN_NETDEV_EVENT";
@@ -11582,6 +11583,14 @@ int netdev_refcnt_read(const struct net_device *dev)
}
EXPORT_SYMBOL(netdev_refcnt_read);
+#if defined(CONFIG_NET_DEV_REFCNT_TRACKER) && defined(CONFIG_KALLSYMS)
+static void dump_netdev_trace_buffer(const struct net_device *dev);
+static void erase_netdev_trace_buffer(const struct net_device *dev);
+#else
+static inline void dump_netdev_trace_buffer(const struct net_device *dev) { }
+static inline void erase_netdev_trace_buffer(const struct net_device *dev) { }
+#endif
+
int netdev_unregister_timeout_secs __read_mostly = 10;
#define WAIT_REFS_MIN_MSECS 1
@@ -11655,11 +11664,16 @@ static struct net_device *netdev_wait_allrefs_any(struct list_head *list)
if (time_after(jiffies, warning_time +
READ_ONCE(netdev_unregister_timeout_secs) * HZ)) {
+ rtnl_lock();
list_for_each_entry(dev, list, todo_list) {
pr_emerg("unregister_netdevice: waiting for %s to become free. Usage count = %d\n",
dev->name, netdev_refcnt_read(dev));
ref_tracker_dir_print(&dev->refcnt_tracker, 10);
+ call_netdevice_notifiers(NETDEV_DEBUG_UNREGISTER, dev);
+ dump_netdev_trace_buffer(dev);
}
+ __rtnl_unlock();
+ rcu_barrier();
warning_time = jiffies;
}
@@ -12059,6 +12073,9 @@ struct net_device *alloc_netdev_mqs(int sizeof_priv, const char *name,
dev->priv_len = sizeof_priv;
+#if defined(CONFIG_NET_DEV_REFCNT_TRACKER) && defined(CONFIG_KALLSYMS)
+ INIT_LIST_HEAD(&dev->netdev_trace_buffer_list);
+#endif
ref_tracker_dir_init(&dev->refcnt_tracker, 128, "netdev");
#ifdef CONFIG_PCPU_DEV_REFCNT
dev->pcpu_refcnt = alloc_percpu(int);
@@ -12158,6 +12175,7 @@ struct net_device *alloc_netdev_mqs(int sizeof_priv, const char *name,
free_pcpu:
#ifdef CONFIG_PCPU_DEV_REFCNT
free_percpu(dev->pcpu_refcnt);
+ erase_netdev_trace_buffer(dev);
free_dev:
#endif
kvfree(dev);
@@ -12226,6 +12244,8 @@ void free_netdev(struct net_device *dev)
free_percpu(dev->pcpu_refcnt);
dev->pcpu_refcnt = NULL;
#endif
+ erase_netdev_trace_buffer(dev);
+
free_percpu(dev->core_stats);
dev->core_stats = NULL;
free_percpu(dev->xdp_bulkq);
@@ -13229,6 +13249,12 @@ static struct smp_hotplug_thread backlog_threads = {
.setup = backlog_napi_setup,
};
+#if defined(CONFIG_NET_DEV_REFCNT_TRACKER) && defined(CONFIG_KALLSYMS)
+static void __init net_dev_refcnt_tracker_init(void);
+#else
+static void __init net_dev_refcnt_tracker_init(void) { };
+#endif
+
/*
* This is called single threaded during boot, so no need
* to take the rtnl semaphore.
@@ -13237,6 +13263,7 @@ static int __init net_dev_init(void)
{
int i, rc = -ENOMEM;
+ net_dev_refcnt_tracker_init();
BUG_ON(!dev_boot_phase);
net_dev_struct_check();
@@ -13340,3 +13367,242 @@ static int __init net_dev_init(void)
}
subsys_initcall(net_dev_init);
+
+#if defined(CONFIG_NET_DEV_REFCNT_TRACKER) && defined(CONFIG_KALLSYMS)
+
+#define NETDEV_TRACE_BUFFER_SIZE 32768
+static struct netdev_trace_buffer {
+ struct list_head list;
+ atomic_t count;
+ int nr_entries;
+ unsigned long entries[20];
+} netdev_trace_buffer[NETDEV_TRACE_BUFFER_SIZE];
+static LIST_HEAD(netdev_trace_buffer_list);
+static DEFINE_RAW_SPINLOCK(netdev_trace_buffer_lock);
+static bool netdev_trace_buffer_exhausted;
+static unsigned long start_of_handle_softirqs __ro_after_init;
+static unsigned long end_of_handle_softirqs __ro_after_init;
+
+static int netdev_trace_buffer_init(void)
+{
+ int i;
+
+ for (i = 0; i < NETDEV_TRACE_BUFFER_SIZE; i++)
+ list_add_tail(&netdev_trace_buffer[i].list, &netdev_trace_buffer_list);
+ return 0;
+}
+pure_initcall(netdev_trace_buffer_init);
+
+static int trim_netdev_trace(unsigned long *entries, int nr_entries)
+{
+ char buffer[32] = { };
+ char *cp;
+ int i;
+
+ for (i = 0; i < nr_entries; i++) {
+ snprintf(buffer, sizeof(buffer) - 1, "%ps", (void *)entries[i]);
+ cp = strchr(buffer, ' ');
+ if (cp)
+ *cp = '\0';
+ if (buffer[0] == 'p') {
+ if (!strcmp(buffer, "process_one_work"))
+ return i + 1;
+ } else if (buffer[0] == 'k') {
+ if (!strcmp(buffer, "ksys_unshare"))
+ return i + 1;
+ } else if (buffer[0] == 's') {
+ if (!strcmp(buffer, "sock_sendmsg_nosec") ||
+ !strcmp(buffer, "sock_recvmsg_nosec"))
+ return i + 1;
+ } else if (buffer[0] == '_') {
+ if (!strcmp(buffer, "__sys_bind") ||
+ !strcmp(buffer, "__sock_release") ||
+ !strcmp(buffer, "__sys_bpf"))
+ return i + 1;
+ } else {
+ if (!strcmp(buffer, "do_sock_setsockopt"))
+ return i + 1;
+ }
+ }
+ return nr_entries;
+}
+
+static void dump_netdev_trace_buffer(const struct net_device *dev)
+{
+ struct netdev_trace_buffer *ptr, *tmp;
+ int count, balance = 0, pos = 0;
+
+ /* Trim common traces. */
+ list_for_each_entry_rcu(ptr, &dev->netdev_trace_buffer_list, list,
+ /* list elements can't go away. */ 1) {
+ ptr->nr_entries = trim_netdev_trace(ptr->entries, ptr->nr_entries);
+ }
+ /* Merge duplicated entries after trimming common traces. */
+ list_for_each_entry_rcu(ptr, &dev->netdev_trace_buffer_list, list,
+ /* list elements can't go away. */ 1) {
+ /* Skip empty entries. */
+ if (!atomic_read(&ptr->count))
+ continue;
+ list_for_each_entry_rcu(tmp, &ptr->list, list,
+ /* list elements can't go away. */ 1) {
+ if (ptr->nr_entries != tmp->nr_entries ||
+ memcmp(ptr->entries, tmp->entries,
+ ptr->nr_entries * sizeof(unsigned long)))
+ continue;
+ /* Skip empty entries. */
+ count = atomic_read(&tmp->count);
+ if (!count)
+ continue;
+ /* Move count from non-first entry to first entry. */
+ atomic_add(count, &ptr->count);
+ atomic_sub(count, &tmp->count);
+ }
+ }
+ /* Report all entries for this device. */
+ list_for_each_entry_rcu(ptr, &dev->netdev_trace_buffer_list, list,
+ /* list elements can't go away. */ 1) {
+ /* Skip empty entries. */
+ count = atomic_read(&ptr->count);
+ if (!count)
+ continue;
+ /* Report this entry. It is safe to call cond_resched() because
+ * this function is called from schedulable context.
+ */
+ pos++;
+ balance += count;
+ pr_info("Call trace for %s[%d] %+d at\n", dev->name, pos, count);
+ stack_trace_print(ptr->entries, ptr->nr_entries, 4);
+ cond_resched();
+ }
+ if (!netdev_trace_buffer_exhausted)
+ pr_info("balance as of %s[%d] is %d\n", dev->name, pos, balance);
+}
+
+static void erase_netdev_trace_buffer(const struct net_device *dev)
+{
+ struct netdev_trace_buffer *ptr;
+ unsigned long flags;
+
+ /* This function is called after free_percpu(dev->pcpu_refcnt) was already
+ * called, which means that no more __dev_put()/__dev_hold() call can be made.
+ * Therefore, no more save_netdev_trace_buffer() call will be made, and we can
+ * safely return list elements to netdev_trace_buffer_list.
+ */
+ raw_spin_lock_irqsave(&netdev_trace_buffer_lock, flags);
+ while (!list_empty(&dev->netdev_trace_buffer_list)) {
+ ptr = list_first_entry(&dev->netdev_trace_buffer_list, typeof(*ptr), list);
+ list_del(&ptr->list);
+ list_add_tail(&ptr->list, &netdev_trace_buffer_list);
+ }
+ raw_spin_unlock_irqrestore(&netdev_trace_buffer_lock, flags);
+}
+
+void save_netdev_trace_buffer(struct net_device *dev, int delta)
+{
+ struct netdev_trace_buffer *ptr;
+ unsigned long entries[ARRAY_SIZE(ptr->entries)];
+ int nr_entries;
+ unsigned long flags;
+
+ /* This function is not NMI-safe. Give up if called from NMI context. */
+ if (in_nmi())
+ return;
+ /* Get stack traces. */
+ nr_entries = stack_trace_save(entries, ARRAY_SIZE(ptr->entries), 1);
+ /* Trim traces of process context now if called from softirq context, for
+ * we will easily exhaust netdev_trace_buffer_list if we don't trim traces
+ * of process context when trying to compare with existing entries.
+ *
+ * Avoid kallsyms lookup, by using cached address resolved upon boot.
+ */
+ if (in_softirq()) {
+ int i;
+
+ for (i = 0; i < nr_entries; i++) {
+ if (entries[i] >= start_of_handle_softirqs &&
+ entries[i] < end_of_handle_softirqs) {
+ nr_entries = i + 1;
+ break;
+ }
+ }
+ }
+ /* Compare with existing entries at best-effort basis. Since duplicated entries
+ * created by race condition will be merged when reporting, we don't use lock here.
+ */
+ list_for_each_entry_rcu(ptr, &dev->netdev_trace_buffer_list, list,
+ /* list elements can't go away. */ 1) {
+ if (ptr->nr_entries == nr_entries &&
+ !memcmp(ptr->entries, entries, nr_entries * sizeof(unsigned long))) {
+ atomic_add(delta, &ptr->count);
+ return;
+ }
+ }
+ /* Add a new entry. We don't re-compare with existing entries with lock held, for
+ * duplicated entries created by race condition will be merged when reporting.
+ * But we use raw spinlock here in case this function is called with some other
+ * raw spinlock already held.
+ */
+ raw_spin_lock_irqsave(&netdev_trace_buffer_lock, flags);
+ if (!list_empty(&netdev_trace_buffer_list)) {
+ /* Remove one entry from netdev_trace_buffer_list and initialize it. */
+ ptr = list_first_entry(&netdev_trace_buffer_list, typeof(*ptr), list);
+ list_del(&ptr->list);
+ atomic_set(&ptr->count, delta);
+ ptr->nr_entries = nr_entries;
+ memmove(ptr->entries, entries, nr_entries * sizeof(unsigned long));
+ /* Append it in RCU manner, for readers are lockless. */
+ list_add_tail_rcu(&ptr->list, &dev->netdev_trace_buffer_list);
+ } else {
+ netdev_trace_buffer_exhausted = true;
+ }
+ raw_spin_unlock_irqrestore(&netdev_trace_buffer_lock, flags);
+}
+EXPORT_SYMBOL(save_netdev_trace_buffer);
+
+struct timer_completion_struct {
+ struct timer_list timer;
+ struct completion completion;
+};
+
+/* Resolve address of handle_softirqs() and cache it, in order to avoid looking up
+ * kallsyms every time.
+ */
+static void __init netdev_addr_resolve_func(struct timer_list *timer)
+{
+ unsigned long entries[40];
+ int nr_entries = stack_trace_save(entries, ARRAY_SIZE(entries), 1);
+ char buffer[KSYM_SYMBOL_LEN] = { };
+ unsigned long offset, size;
+ char *cp;
+ int i;
+
+ for (i = 0; i < nr_entries; i++) {
+ sprint_symbol(buffer, entries[i]);
+ if (strncmp(buffer, "handle_softirqs", 15))
+ continue;
+ cp = strchr(buffer, '+');
+ if (!cp || sscanf(cp, "+%lx/%lx", &offset, &size) != 2)
+ continue;
+ start_of_handle_softirqs = entries[i] - offset;
+ end_of_handle_softirqs = start_of_handle_softirqs + size;
+ break;
+ }
+ complete(&container_of(timer, struct timer_completion_struct, timer)->completion);
+}
+
+static void __init net_dev_refcnt_tracker_init(void)
+{
+ struct timer_completion_struct tc;
+
+ timer_setup_on_stack(&tc.timer, netdev_addr_resolve_func, 0);
+ init_completion(&tc.completion);
+ /* Schedule a call to netdev_addr_resolve_func(). */
+ mod_timer(&tc.timer, jiffies);
+ /* Wait for netdev_addr_resolve_func() to be called. */
+ wait_for_completion(&tc.completion);
+ /* Wait for netdev_addr_resolve_func() to complete. */
+ timer_delete_sync(&tc.timer);
+ timer_destroy_on_stack(&tc.timer);
+}
+
+#endif
diff --git a/net/core/lock_debug.c b/net/core/lock_debug.c
index 8a81c5430705..c1a44594c492 100644
--- a/net/core/lock_debug.c
+++ b/net/core/lock_debug.c
@@ -29,6 +29,7 @@ int netdev_debug_event(struct notifier_block *nb, unsigned long event,
case NETDEV_DOWN:
case NETDEV_REBOOT:
case NETDEV_UNREGISTER:
+ case NETDEV_DEBUG_UNREGISTER:
case NETDEV_CHANGEMTU:
case NETDEV_CHANGEADDR:
case NETDEV_PRE_CHANGEADDR:
diff --git a/net/socket.c b/net/socket.c
index 63c69a0fa74e..af7e99636495 100644
--- a/net/socket.c
+++ b/net/socket.c
@@ -698,7 +698,11 @@ struct socket *sock_alloc(void)
}
EXPORT_SYMBOL(sock_alloc);
-static void __sock_release(struct socket *sock, struct inode *inode)
+static
+#if defined(CONFIG_NET_DEV_REFCNT_TRACKER) && defined(CONFIG_KALLSYMS)
+noinline
+#endif
+void __sock_release(struct socket *sock, struct inode *inode)
{
const struct proto_ops *ops = READ_ONCE(sock->ops);
@@ -770,7 +774,13 @@ static noinline void call_trace_sock_send_length(struct sock *sk, int ret,
trace_sock_send_length(sk, ret, 0);
}
-static inline int sock_sendmsg_nosec(struct socket *sock, struct msghdr *msg)
+static
+#if defined(CONFIG_NET_DEV_REFCNT_TRACKER) && defined(CONFIG_KALLSYMS)
+noinline
+#else
+inline
+#endif
+int sock_sendmsg_nosec(struct socket *sock, struct msghdr *msg)
{
int ret = INDIRECT_CALL_INET(READ_ONCE(sock->ops)->sendmsg, inet6_sendmsg,
inet_sendmsg, sock, msg,
@@ -1120,8 +1130,13 @@ static noinline void call_trace_sock_recv_length(struct sock *sk, int ret, int f
trace_sock_recv_length(sk, ret, flags);
}
-static inline int sock_recvmsg_nosec(struct socket *sock, struct msghdr *msg,
- int flags)
+static
+#if defined(CONFIG_NET_DEV_REFCNT_TRACKER) && defined(CONFIG_KALLSYMS)
+noinline
+#else
+inline
+#endif
+int sock_recvmsg_nosec(struct socket *sock, struct msghdr *msg, int flags)
{
int ret = INDIRECT_CALL_INET(READ_ONCE(sock->ops)->recvmsg,
inet6_recvmsg,
@@ -2624,9 +2639,12 @@ static int copy_msghdr_from_user(struct msghdr *kmsg,
return err < 0 ? err : 0;
}
-static int ____sys_sendmsg(struct socket *sock, struct msghdr *msg_sys,
- unsigned int flags, struct used_address *used_address,
- unsigned int allowed_msghdr_flags)
+static
+#if defined(CONFIG_NET_DEV_REFCNT_TRACKER) && defined(CONFIG_KALLSYMS)
+noinline
+#endif
+int ____sys_sendmsg(struct socket *sock, struct msghdr *msg_sys, unsigned int flags,
+ struct used_address *used_address, unsigned int allowed_msghdr_flags)
{
unsigned char ctl[sizeof(struct cmsghdr) + 20]
__aligned(sizeof(__kernel_size_t));
--
2.55.0