Re: Kernel freeze on killall kissattach

[Thomas Osterried <thomas@osterried.de>]

Hello,

thank you Roland for bringing this up.

I also have prepared a posting to this list; but I liked to first discuss the
new problem with the authors of the patch that caused the regression.

I'll try to keep it short:

Starting with commit 1ade48d0c27d5da1ccf4b583d8c5fc8b534a3ac8
(author	Lin Ma <linma@zju.edu.cn>	2021-12-17 10:29:41 +0800)
kernel will panic if
  1. there's an active connection
AND
  2. you kill kissattach (or rmmod bpqether, etc)


The patch above tries to fix a problem that hhas been in the kernel for many years,
but rarely occured (possible nullpointer exception in ax25_sendmsg()).


This new bug caused by patch 1ade48d0c27d5da1ccf4b583d8c5fc8b534a3ac8 is already
in current linux distributions, like debian bullseye (comes with kernel version 5.10).


Unfortunately, that patch has a real stability impact:
In the kernel trace message I'll append below (Appendix I) we see, that the kernel
panics due to null pointer exception.

Lin Ma tried to assure in ax25_kill_by_device socket locking,
before setting s->ax25_dev to NULL:
+			lock_sock(s->sk);
+			s->ax25_dev = NULL;

But:
s->sk can be NULL.
lock_sock(NULL) leads to kernel panic.


You may argue: can s->sk be NULL, or is there another bug somewhere that should
be fixed instead?
Maybe, but: until we really understand what causes s->sk to be NULL in some situations
(and we'll hav found really all such possible cases), we'll have to assure that we
don't lock_sock(NULL).

The sense of the new lock_sock() is to assure that "s->ax25_dev = NULL" will not cause
a null pointer deference in ax25_sendmsg() [and may be other functions in
the ax25 protocol stack].
On the other hand, if we don't set s->ax25_dev = NULL, it may point to a free()'d
structure, after the device is free'd.


Consider the following as a quick fix (it's tested) against the kernel panic,
caused by 1ade48d0c27d5da1ccf4b583d8c5fc8b534a3ac8:

diff -up  a/af_ax25.c b/af_ax25.c 
--- a/net/ax25/af_ax25.c	2022-02-26 15:30:35.529637338 +0100
+++ b/net/ax25/af_ax25.c	2022-02-26 15:34:08.789076313 +0100
@@ -86,10 +86,16 @@ again:
 	ax25_for_each(s, &ax25_list) {
 		if (s->ax25_dev == ax25_dev) {
 			spin_unlock_bh(&ax25_list_lock);
+			if (!s->sk) {
+				ax25_dev = NULL;
+				ax25_disconnect(s, ENETUNREACH);
+				goto out;
+			}
 			lock_sock(s->sk);
 			s->ax25_dev = NULL;
-			release_sock(s->sk);
 			ax25_disconnect(s, ENETUNREACH);
+			release_sock(s->sk);
+out:
 			spin_lock_bh(&ax25_list_lock);
 
 			/* The entry could have been deleted from the



Keep in mind, that in situation of s->sk == NULL
  ax25_dev = NULL;
may still lead to a situation that 1ade48d0c27d5da1ccf4b583d8c5fc8b534a3ac8
tried to fix.



If we look at torwald's kernel tree (which is currently up to kernel netdev tree),
or you remember patches of jan / feb 2022 that we've seen on this list
(i.e. 4e0f718daf97), the code around lock_sock() in ax25_kill_by_device() has
changed again (and reordered the call of some functions).

-> My approach to q&d-fix is this:

--- a/af_ax25.c	2022-02-25 11:49:19.000000000 +0100
+++ b/af_ax25.c	2022-03-01 04:15:16.000000000 +0100
@@ -86,7 +86,13 @@ static void ax25_kill_by_device(struct n
 again:
 	ax25_for_each(s, &ax25_list) {
 		if (s->ax25_dev == ax25_dev) {
-			sk = s->sk;
+			if (!(sk = s->sk)) {
+				s->ax25_dev = NULL;
+				spin_unlock_bh(&ax25_list_lock);
+				ax25_disconnect(s, ENETUNREACH);
+				spin_lock_bh(&ax25_list_lock);
+				goto again;
+			}
 			sock_hold(sk);
 			spin_unlock_bh(&ax25_list_lock);
 			lock_sock(sk);




Apart from this: a new regression:

With patch d01ffb9eee4af165d83b08dd73ebdf9fe94a519b , 
"ax25: add refcount in ax25_dev to avoid UAF bugs"
new reference counters for ax25_dev came in.

If you test kernel torwalds tree, we have two problems:
1. the kernel panics, as described above (happens when
    current connected ax25-sessions and you do a killall kissattach)
2. a new regression:
   if you use Roland's example and do
   1. killall axcall
   2. netstat -an
      here you see the well-known ax25-ex-connected-session-now-listening-state-bug:
      Active AX.25 sockets
      Dest       Source     Device  State        Vr/Vs    Send-Q  Recv-Q
      DL9SAU-4   DL9SAU-3   ax0     LISTENING    000/000  0       0     
   3. Now, you do killall kissattach
      -> kernel complains in intervall:
        unregister_netdevice: waiting for ax1 to become free. Usage count = 2
      and this situation lasts for ever.
      We know, that nothing cleans up those dead ex-sessions in listening-state.
      More trace: see Appendix II.
   4. In such a situation, you cannot do anymore, without rebooting,
       rmmod ax25 and rmmod mkiss 



Final wish:
please let's talk with each other (may be first in private with someone else,
then on this list), before sending a patch to the netdev maintainers.
At least the two problems I've described took only few time of testing and
I stumbled over the problems they introduced.


Two appendixes below.


vy 73,
	- Thomas  dl9sau



Appendix I:
-----------

debian bullseye kernel 5.10, as well as current linux torvalds tree:

kernel panic after killall kissattach when connections are still active:
 
[65483.936924] BUG: kernel NULL pointer dereference, address: 0000000000000088
[65483.937138] #PF: supervisor write access in kernel mode
[65483.937249] #PF: error_code(0x0002) - not-present page
[65483.937371] PGD 0 P4D 0 
[65483.937447] Oops: 0002 [#1] SMP NOPTI
[65483.937547] CPU: 0 PID: 337635 Comm: kissattach Tainted: G            E     5.10.0-11-amd64 #1 Debian 5.10.92-1
[65483.937739] Hardware name: QEMU Standard PC (Q35 + ICH9, 2009), BIOS 1.14.0-2 04/01/2014
[65483.937908] RIP: 0010:_raw_spin_lock_bh+0x17/0x30
[65483.938023] Code: 00 57 9d 0f 1f 44 00 00 c3 66 2e 0f 1f 84 00 00 00 00 00 0f 1f 44 00 00 65 81 05 40 65 95 54 00 02 00 00 31 c0 ba 01 00 00 00 <f0> 0f b1 17 75 01 c3 89 c6 e8 bb 14 82 ff 66 90 c3 0f 1f 84 00 00
[65483.938349] RSP: 0018:ffffac24c0c43c48 EFLAGS: 00010246
[65483.938466] RAX: 0000000000000000 RBX: 0000000000000000 RCX: 0000000000000002
[65483.938606] RDX: 0000000000000001 RSI: 0000000000000000 RDI: 0000000000000088
[65483.938755] RBP: 0000000000000088 R08: 0000000000000000 R09: 0000000000000002
[65483.938902] R10: ffff9622081b9000 R11: 0000000000000000 R12: ffff9622044be000
[65483.939049] R13: 00000000ffffffea R14: ffff9622044be078 R15: ffffac24c0c43d60
[65483.939207] FS:  00007f606b22b740(0000) GS:ffff96227dc00000(0000) knlGS:0000000000000000
[65483.939371] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
[65483.939497] CR2: 0000000000000088 CR3: 0000000014344000 CR4: 00000000000006f0
[65483.939648] Call Trace:
[65483.939732]  lock_sock_nested+0x1e/0x60
[65483.939856]  ax25_device_event+0x89/0xe0 [ax25]
[65483.939969]  raw_notifier_call_chain+0x44/0x60
[65483.940078]  dev_close_many+0xef/0x150
[65483.940175]  rollback_registered_many+0x152/0x6c0
[65483.940337]  ? __schedule+0x28a/0x870
[65483.940450]  unregister_netdevice_queue+0xcf/0x180
[65483.940571]  unregister_netdev+0x18/0x20
[65483.940680]  mkiss_close+0x77/0xb0 [mkiss]
[65483.940791]  tty_ldisc_release+0x8f/0x180
[65483.940896]  tty_release_struct+0x13/0x80
[65483.941003]  tty_release+0x437/0x5d0
[65483.941105]  __fput+0x95/0x240
[65483.941195]  task_work_run+0x65/0xa0
[65483.941294]  do_exit+0x362/0xaa0
[65483.941389]  do_group_exit+0x33/0xa0
[65483.941489]  __x64_sys_exit_group+0x14/0x20
[65483.941601]  do_syscall_64+0x33/0x80
[65483.941700]  entry_SYSCALL_64_after_hwframe+0x44/0xa9
[65483.941820] RIP: 0033:0x7f606b2f9699
[65483.941915] Code: Unable to access opcode bytes at RIP 0x7f606b2f966f.



Appendix II:
------------

current linux torvalds tree:
killall axcall; one connection still in listening state; killall kissattach

	...
	[  321.386733] unregister_netdevice: waiting for ax1 to become free. Usage count = 2
	[  331.467128] unregister_netdevice: waiting for ax1 to become free. Usage count = 2
	[  341.547385] unregister_netdevice: waiting for ax1 to become free. Usage count = 2
	[  351.627710] unregister_netdevice: waiting for ax1 to become free. Usage count = 2
	[  361.707951] unregister_netdevice: waiting for ax1 to become free. Usage count = 2
	[  363.692092] INFO: task kissattach:508 blocked for more than 120 seconds.
	[  363.692321]       Tainted: G            E     5.17.0-rc6+ #4
	[  363.692444] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
	[  363.692782] task:kissattach      state:D stack:    0 pid:  508 ppid:     1 flags:0x00000002
	[  363.693034] Call Trace:
	[  363.693201]  <TASK>
	[  363.693451]  __schedule+0x302/0x9a0
	[  363.693605]  schedule+0x4e/0xc0
	[  363.693730]  schedule_preempt_disabled+0x14/0x20
	[  363.693860]  __mutex_lock.constprop.0+0x2b4/0x460
	[  363.694009]  ? mod_objcg_state+0x107/0x300
	[  363.694134]  tty_release+0x4f/0x5e0
	[  363.694217]  ? memcg_slab_free_hook+0xcc/0x190
	[  363.694420]  __fput+0x8c/0x240
	[  363.694575]  task_work_run+0x5c/0x90
	[  363.694749]  do_exit+0x331/0xae0
	[  363.694913]  do_group_exit+0x2d/0x90
	[  363.697440]  __x64_sys_exit_group+0x14/0x20
	[  363.699904]  do_syscall_64+0x3b/0xc0
	[  363.702246]  entry_SYSCALL_64_after_hwframe+0x44/0xae
	[  363.704704] RIP: 0033:0x7f7dd46f7699
	[  363.706998] RSP: 002b:00007fff436d7088 EFLAGS: 00000246 ORIG_RAX: 00000000000000e7
	[  363.709437] RAX: ffffffffffffffda RBX: 00007f7dd47ec610 RCX: 00007f7dd46f7699
	[  363.711905] RDX: 000000000000003c RSI: 00000000000000e7 RDI: 0000000000000000
	[  363.714273] RBP: 0000000000000000 R08: ffffffffffffff80 R09: 0000000000000001
	[  363.716735] R10: 00007f7dd4825440 R11: 0000000000000246 R12: 00007f7dd47ec610
	[  363.719093] R13: 0000000000000001 R14: 00007f7dd47ecae8 R15: 0000000000000000
	[  363.721539]  </TASK>
	[  371.788201] unregister_netdevice: waiting for ax1 to become free. Usage count = 2
	[  381.868436] unregister_netdevice: waiting for ax1 to become free. Usage count = 2
	[  391.948686] unregister_netdevice: waiting for ax1 to become free. Usage count = 2
	...




On Sun, Mar 06, 2022 at 03:18:14PM +0100, Roland Schwarz wrote:
> Dear All,
> 
> please correct me if I am wrong, but as I understand it should not be
> possible to trigger a kernel freeze by just killing user space processes.
> 
> While trying to understand a certain behavior of the ax25 driver I came up
> with a small test case which I ran in a virtual machine (KVM):
> 
> First I tried with a kernel from Linus tree:
> 
> uname -r
> 5.17.0-rc6+
> 
> cat /etc/ax25/axports
> ax0     OE1RSA-0        115200  255     7       Test A
> ax1     OE1RSA-1        115200  255     7       Test B
> 
> sudo kissattach /dev/ptmx ax0
> AX.25 port ax0 bound to device ax0
> Awaiting client connects on
> /dev/pts/1
> 
> sudo kissattach /dev/pts/1 ax1
> AX.25 port ax1 bound to device ax1
> 
> axcall ax1 OE1RSA-0
> 
> Now in a second terminal:
> sudo killall kissattach
> 
> First terminal:
> GW4PTS AX.25 Connect v1.11
> Trying...
> *** Connected to OE1RSA-0
> *** Cleared
> 
> ==> But: Kernel freezes
> 
> I can see this behaviour also in the debian kernel:
> 
> uname -r
> 5.10.0-11-amd64
> 
> This kernel also freezes. I suspect this to be a bug because if I try to
> reboot the machine instead of the killall command the machine does not shut
> off and reboot which is a problem with a remotely installed system.
> 
> Any ideas?
> 
> 73 de Roland oe1rsa
> 
> -- 
> __________________________________________
>   _  _  | Roland Schwarz
>  |_)(_  |
>  | \__) | mailto:roland.schwarz@blackspace.at
> ________| http://www.blackspace.at