Re: Suggestions on how to debug kernel crashes where printk and gdb both does not work

On Tue, Jun 15, 2021 at 4:30 AM Pavel Skripkin [off-list ref] wrote:

On Mon, 14 Jun 2021 23:04:03 +0800
Dongliang Mu [off-list ref] wrote:

quoted

On Mon, Jun 14, 2021 at 10:47 PM Pavel Skripkin
[off-list ref] wrote:

quoted

On Mon, 14 Jun 2021 22:40:55 +0800
Dongliang Mu [off-list ref] wrote:

quoted

On Mon, Jun 14, 2021 at 10:25 PM Pavel Skripkin
[off-list ref] wrote:

quoted

On Mon, 14 Jun 2021 22:19:10 +0800
Dongliang Mu [off-list ref] wrote:

quoted

On Mon, Jun 14, 2021 at 9:34 PM Pavel Skripkin
[off-list ref] wrote:

quoted

On Mon, 14 Jun 2021 21:22:43 +0800
Dongliang Mu [off-list ref] wrote:

quoted

Dear kernel developers,

I was trying to debug the crash - memory leak in
hwsim_add_one [1] recently. However, I encountered a
disgusting issue: my breakpoint and printk/pr_alert in the
functions that will be surely executed do not work. The
stack trace is in the following. I wrote this email to
ask for some suggestions on how to debug such cases?

Thanks very much. Looking forward to your reply.

Hi, Dongliang!

This bug is not similar to others on the dashboard. I spent
some time debugging it a week ago. The main problem here,
that memory allocation happens in the boot time:

quoted

[<ffffffff84359255>] kernel_init+0xc/0x1a7
init/main.c:1447

Oh, nice catch. No wonder why my debugging does not work. :(

quoted

and reproducer simply tries to
free this data. You can use ftrace to look at it. Smth like
this:

$ echo 'hwsim_*' > $TRACE_DIR/set_ftrace_filter

Thanks for your suggestion.

Do you have any conclusions about this case? If you have found
out the root cause and start writing patches, I will turn my
focus to other cases.

No, I had some busy days and I have nothing about this bug for
now. I've just traced the reproducer execution and that's all :)

I guess, some error handling paths are broken, but Im not sure

In the beginning, I agreed with you. However, after I manually
checked functions: hwsim_probe (initialization) and  hwsim_remove
(cleanup), then things may be different. The cleanup looks
correct to me. I would like to debug but stuck with the debugging
process.

And there is another issue: the cleanup function also does not
output anything or hit the breakpoint. I don't quite understand
it since the cleanup is not at the boot time.

Any idea?

Output from ftrace (syzkaller repro):

root@syzkaller:~# cat /sys/kernel/tracing/trace
# tracer: function_graph
#
# CPU  DURATION                  FUNCTION CALLS
# |     |   |                     |   |   |   |
 1)               |  hwsim_del_radio_nl() {
 1)               |    hwsim_del() {
 1)               |      hwsim_edge_unsubscribe_me() {
 1) ! 310.041 us  |        hwsim_free_edge();
 1) ! 665.221 us  |      }
 1) * 52999.05 us |    }
 1) * 53035.38 us |  }

Cleanup function is not the case, I think :)

It seems like I spot the incorrect cleanup function (hwsim_remove is
the right one is in my mind). Let me learn how to use ftrace to log
the executed functions and then discuss this case with you guys.

Hmmm, I think, there is a mess with lists.

I just want to share my debug results, I have no idea about the fix for
now.

In hwsim_probe() edge for phy->idx = 1 is allocated, then reproduces
sends a request to delete phy with idx == 0, so this check in
hwsim_edge_unsubscribe_me():

        if (e->endpoint->idx == phy->idx) {
                ... clean up code ...
        }

won't be passed and edge won't be freed (because it was allocated for
phy with idx == 1). Allocated edge for phy 1 becomes leaked after
hwsim_del(). I can't really see the code where phy with idx == 1 can
be deleted from list...

Thanks for sharing your debugging result.

              hwsim_phys
                       |
   ---------------------------------
   |                                      |
sub0 (edges)                 sub1 (edges)
   ----> e (idx = 1)               ----> e (idx = 0)

hwsim_del_radio_nl will call hwsim_del to delete phy (idx:1).
However, in this function, it only deletes the e in the edge list of sub1.
Then it deletes phy (i.e., sub0) from the hwsim_phys list. So it
leaves the e in the edge list of sub0 non-free.

I proposed a patch and test it successfully in the syzbot dashboard.

diff --git a/drivers/net/ieee802154/mac802154_hwsim.c

b/drivers/net/ieee802154/mac802154_hwsim.c
index da9135231c07..b05159cff33a 100644

--- a/drivers/net/ieee802154/mac802154_hwsim.c
+++ b/drivers/net/ieee802154/mac802154_hwsim.c

@@ -824,9 +824,16 @@ static int hwsim_add_one(struct genl_info *info,

struct device *dev,
 static void hwsim_del(struct hwsim_phy *phy)
 {
  struct hwsim_pib *pib;
+ struct hwsim_edge *e;

  hwsim_edge_unsubscribe_me(phy);

+ // remove the edges in the list
+ list_for_each_entry_rcu(e, &phy->edges, list) {
+ list_del_rcu(&e->list);
+ hwsim_free_edge(e);
+ }
+
  list_del(&phy->list);

  rcu_read_lock();

 I will send a patch later.

Maybe, it's kmemleak bug. Similar strange case was with this one
https://syzkaller.appspot.com/bug?id=3a325b8389fc41c1bc94de0f4ac437ed13cce584.
I find it strange, that I could reach leaked pointers after kmemleak reported a
leak. Im not familiar with kmemleak internals and I might be wrong


With regards,
Pavel Skripkin