Re: [ROSE] [AX25] 6.15.10 long term stable kernel oops

[F6BVP <f6bvp@free.fr>]

[-- Attachment #1: Type: text/plain, Size: 3074 bytes --]

Hi Eric,

I finally found the instruction triggering the bug in 
tty_ldisc_receive_buf()

Being absolutely new in kernel debugging, I read 
Documentation/admin-guide/bug-hunting.rst in order to see what I needed 
to do :
./scripts/config -d COMPILE_TEST -e DEBUG_KERNEL -e DEBUG_INFO

I also installed netconsole driver to capture Oops and received it on a 
local RaspBerry Pi with socat :
nohup socat -u udp-recv:6666 ./netconsole.log < /dev/null > /dev/null 2>&1 &

In function tty_ldisc_receive_buf() , call to receive_buf() goes well as 
long as count is small whereas with large number of bytes there is a 
kernel BUG NULL pointer dereference.

Included is the last netconsole log I captured and only kept last pages.

If with analyze netconsole.log from 4,19279,15377986 we see three 
sequences from tty_port_default_receive_buf to tty_ldisc_receive_buf 
giving the number of bytes processed.

If we concentrate on sequence __tty_insert_flip_string_flags that gives 
the number of copied bytes we see that just before the BUG something 
goes differently when bytes number is relatively high i.e. 272 in our case.
There is yet another tty_ldisc_deref after flush_to_ldisc and before 
receive_buf.

In netconsole.log (4,19284,1537778017) call to receive_buf() is fine 
with count value equal 18 bytes.

With line sequence (see below) 411, line 416, line 427 everything goes 
well when byte count is <=28 in our report.
On the contrary the sequence line 416, line 421, if bytes count is 
bigger (272), line 427 is not reached which means that

ld->ops->receive_buf(ld->tty, p, f, count);

never returns.

As a proof I commented this line of code and the BUG dissapeared... Of 
course the application did not achieved the AX25 connexion, waiting for 
a reply.

Here I am. Next step is probably to discover why the call to 
receive_buf() fails when bytes are not small and tty_ldisc_deref() is 
acting after flush_to_ldisc probably leading to an error. What value is 
wrong ? ld->tty , p, f ?

Regards,

Bernard


Here here tty_ldisc_receive_buf() with line numbers added to printk() lines:

size_t tty_ldisc_receive_buf(struct tty_ldisc *ld, const u8 *p, const u8 *f,
			     size_t count)
{

	if (ld->ops->receive_buf2)
	{
		count = ld->ops->receive_buf2(ld->tty, p, f, count);
		
L411		printk("Here I am: %s:%d count:%ld bytes 
buf2\n",__FUNCTION__,__LINE__,count);
	}
	else {
		count = min_t(size_t, count, ld->tty->receive_room);
	
L416		printk("Here I am: %s:%d count:%ld bytes tty 
receive_room\n",__FUNCTION__,__LINE__,count);

		if (count && ld->ops->receive_buf)
		{

L421			printk("Here I am: %s:%d count:%ld bytes ---> 
receive_buf\n",__FUNCTION__,__LINE__,count);
	
			ld->ops->receive_buf(ld->tty, p, f, count);
		}
	}
	
L427	printk("Here I am: %s:%d count:%ld bytes 
processed\n",__FUNCTION__,__LINE__,count);

	
	return count;
}
EXPORT_SYMBOL_GPL(tty_ldisc_receive_buf);


Le 26/08/2025 à 15:36, Eric Dumazet a écrit :
> 
> Make sure to add symbols to these logs, otherwise we can not really help.
> 
> cat CRASH | scripts/decode_stacktrace.sh ./vmlinux

[-- Attachment #2: netconsole.log --]
[-- Type: text/plain, Size: 8519 bytes --]


4,19278,153777981,-;Here I am: tty_ldisc_receive_buf:427 count:18 bytes processed
4,19279,153777986,-;Here I am: tty_port_default_receive_buf:46 count:18
4,19280,153777991,-;Here I am: tty_ldisc_deref:283 !tty
4,19281,153777996,-;Here I am: __tty_insert_flip_string_flags:351 14 copied
4,19282,153778009,-;Here I am: tty_ldisc_deref:283 !tty
4,19283,153778010,-;Here I am: flush_to_ldisc:506
4,19284,153778017,-;Here I am: receive_buf:479
4,19285,153778023,-;Here I am: n_tty_receive_buf_common:1686
4,19286,153778028,-;Here I am: tty_ldisc_deref:283 !tty
4,19287,153778037,-;Here I am: tty_ldisc_receive_buf:411 count:14 bytes buf2
4,19288,153778043,-;Here I am: tty_ldisc_receive_buf:427 count:14 bytes processed
4,19289,153778048,-;Here I am: tty_port_default_receive_buf:46 count:14
4,19290,153778053,-;Here I am: tty_ldisc_deref:283 !tty
4,19291,153778067,-;Here I am: tty_ldisc_deref:283 !tty
4,19292,153778072,-;Here I am: tty_ldisc_deref:283 !tty
4,19293,153778093,-;Here I am: tty_ldisc_deref:283 !tty
4,19294,153778105,-;Here I am: tty_ldisc_deref:283 !tty
4,19295,153778109,-;Here I am: tty_ldisc_deref:283 !tty
4,19296,153778112,-;Here I am: tty_ldisc_deref:283 !tty
4,19297,153778126,-;Here I am: __tty_insert_flip_string_flags:351 14 copied
4,19298,153778130,-;Here I am: tty_ldisc_deref:283 !tty
4,19299,153778134,-;Here I am: flush_to_ldisc:506
4,19300,153778136,-;Here I am: receive_buf:479
4,19301,153778138,-;Here I am: n_tty_receive_buf_common:1686
4,19302,153778147,-;Here I am: tty_ldisc_receive_buf:411 count:14 bytes buf2
4,19303,153778152,-;Here I am: tty_ldisc_receive_buf:427 count:14 bytes processed
4,19304,153778157,-;Here I am: tty_port_default_receive_buf:46 count:14
4,19305,153778161,-;Here I am: tty_ldisc_deref:283 !tty
4,19306,153778162,-;Here I am: tty_ldisc_deref:283 !tty
4,19307,153778169,-;Here I am: tty_ldisc_deref:283 !tty
4,19308,153778425,-;Here I am: tty_ldisc_deref:283 !tty
4,19309,153778450,-;Here I am: tty_ldisc_deref:283 !tty
4,19310,153778457,-;Here I am: tty_ldisc_deref:283 !tty
4,19311,153778469,-;Here I am: tty_ldisc_deref:283 !tty
4,19312,153778480,-;Here I am: tty_ldisc_deref:283 !tty
6,19313,153778507,-;mkiss: ax0: Trying crc-flexnet
4,19314,153778518,-;Here I am: __tty_insert_flip_string_flags:351 28 copied
4,19315,153778551,-;Here I am: flush_to_ldisc:506
4,19316,153778557,-;Here I am: receive_buf:479
4,19317,153778566,-;Here I am: n_tty_receive_buf_common:1686
4,19318,153778579,-;Here I am: tty_ldisc_receive_buf:411 count:28 bytes buf2
4,19319,153778584,-;Here I am: tty_ldisc_receive_buf:427 count:28 bytes processed
4,19320,153778592,-;Here I am: tty_port_default_receive_buf:46 count:28
4,19321,153778600,-;Here I am: tty_ldisc_deref:283 !tty
4,19322,153778615,-;Here I am: tty_ldisc_deref:283 !tty
4,19323,153778637,-;Here I am: tty_ldisc_deref:283 !tty
4,19324,153778643,-;Here I am: tty_ldisc_deref:283 !tty
4,19325,153778879,-;Here I am: tty_ldisc_deref:283 !tty
4,19326,153779283,-;Here I am: tty_ldisc_deref:283 !tty
4,19327,153779328,-;Here I am: tty_ldisc_deref:283 !tty
4,19328,153786849,-;Here I am: tty_ldisc_deref:283 !tty
4,19329,153786875,-;Here I am: __tty_insert_flip_string_flags:351 272 copied
4,19330,153786882,-;Here I am: tty_ldisc_deref:283 !tty
4,19331,153786888,-;Here I am: flush_to_ldisc:506
4,19332,153786891,-;Here I am: tty_ldisc_deref:283 !tty
4,19333,153786897,-;Here I am: receive_buf:479
4,19334,153786902,-;Here I am: tty_ldisc_receive_buf:416 count:272 bytes tty receive_room
4,19335,153786906,-;Here I am: tty_ldisc_receive_buf:421 count:272 bytes ---> receive_buf
1,19336,153786932,-;BUG: kernel NULL pointer dereference, address: 00000000000000d0
1,19337,153786937,-;#PF: supervisor read access in kernel mode
1,19338,153786955,-;#PF: error_code(0x0000) - not-present page
6,19339,153786960,-;PGD 0 
4,19340,153786960,-;Here I am: tty_ldisc_deref:283 !tty
4,19341,153786967,c;P4D 0 
4,19342,153786972,-;Oops: Oops: 0000 [#1] SMP PTI
4,19343,153786972,-;Here I am: tty_ldisc_deref:283 !tty
4,19344,153786981,-;CPU: 3 UID: 0 PID: 48 Comm: kworker/u16:2 Not tainted 6.17.0-rc2-f6bvp+ #25 PREEMPT(voluntary) 
4,19345,153786986,-;Here I am: __tty_insert_flip_string_flags:351 215 copied
4,19346,153786988,-;Hardware name: To be filled by O.E.M. To be filled by O.E.M./CK3, BIOS 5.011 09/16/2020
4,19347,153786990,-;Workqueue: events_unbound flush_to_ldisc
4,19348,153786998,-;Here I am: tty_ldisc_deref:283 !tty
4,19349,153787003,-;Here I am: tty_ldisc_deref:283 !tty
4,19350,153787005,-;RIP: 0010:__netif_receive_skb_core.constprop.0+0xfe5/0x12d0
4,19351,153787009,-;Here I am: __tty_buffer_request_room:304 size:253
4,19352,153787011,-;Code: 6c 0f 82 24 01 00 00 48 01 93 c0 00 00 00 e9 52 f5 ff ff 48 89 df 4d 89 f5 e8 e7 b4 fd ff e9 c9 fd ff ff 4c 8d 88 d0 00 00 00 <48> 8b 80 d0 00 00 00 4c 8d 78 c8 49 39 c1 0f 84 6c fa ff ff 44 88
4,19353,153787015,-;RSP: 0018:ffffd13040184c98 EFLAGS: 00010286
4,19379,153787121,-;CR2: 00000000000000d0 CR3: 00000001a5440002 CR4: 00000000001726f0
4,19380,153787124,-;Call Trace:
4,19381,153787128,-;Here I am: __tty_insert_flip_string_flags:351 253 copied
4,19382,153787131,-;Here I am: tty_ldisc_deref:283 !tty
4,19383,153787133,-;Here I am: flush_to_ldisc:506
4,19384,153787135,-;Here I am: receive_buf:479
4,19385,153787137,-;Here I am: n_tty_receive_buf_common:1686
4,19386,153787140,-;Here I am: tty_ldisc_receive_buf:411 count:253 bytes buf2
4,19387,153787142,-;Here I am: tty_ldisc_receive_buf:427 count:253 bytes processed
4,19388,153787144,-;Here I am: tty_port_default_receive_buf:46 count:253
4,19389,153787145,-;Here I am: tty_ldisc_deref:283 !tty
4,19390,153787149,-;Here I am: tty_ldisc_deref:283 !tty
4,19391,153787164,-;Here I am: tty_ldisc_deref:283 !tty
4,19392,153787167,-;Here I am: tty_ldisc_deref:283 !tty
4,19393,153787176,-;Here I am: tty_ldisc_deref:283 !tty
4,19394,153787183,-;Here I am: tty_ldisc_deref:283 !tty
4,19395,153787189,-; <IRQ>
4,19396,153787257,-;Here I am: tty_ldisc_deref:283 !tty
4,19397,153787259,-;Here I am: tty_ldisc_deref:283 !tty
4,19398,153787265,-; __netif_receive_skb_one_core+0x3d/0xa0
4,19399,153787407,-; __netif_receive_skb+0x15/0x60
4,19400,153787414,-; process_backlog+0x90/0x160
4,19401,153787421,-; __napi_poll+0x33/0x230
4,19402,153787485,-; net_rx_action+0x20b/0x3f0
4,19403,153787493,-; ? update_process_times+0x89/0xd0
4,19404,153787504,-; handle_softirqs+0xe7/0x340
4,19405,153787512,-; __do_softirq+0x10/0x18
4,19406,153787519,-; do_softirq.part.0+0x3f/0x80
4,19407,153787526,-; </IRQ>
4,19408,153787530,-; <TASK>
4,19409,153787535,-; __local_bh_enable_ip+0x6e/0x70
4,19410,153787542,-; _raw_spin_unlock_bh+0x1d/0x30
4,19411,153787553,-; mkiss_receive_buf+0x36b/0x4b0 [mkiss]
4,19412,153787562,-; tty_ldisc_receive_buf+0xed/0x100
4,19413,153787569,-; tty_port_default_receive_buf+0x43/0xd0
4,19414,153787576,-; flush_to_ldisc+0xf9/0x1f0
4,19415,153787582,-; ? queue_delayed_work_on+0x81/0x90
4,19416,153787603,-; process_one_work+0x191/0x3e0
4,19417,153787609,-; worker_thread+0x2e3/0x420
4,19418,153787615,-; ? __pfx_worker_thread+0x10/0x10
4,19419,153787621,-; kthread+0x10d/0x230
4,19420,153787627,-; ? __pfx_kthread+0x10/0x10
3,19429,153871289,-;pstore: backend (efi_pstore) writing error (-5)
4,19430,153871296,-;RIP: 0010:__netif_receive_skb_core.constprop.0+0xfe5/0x12d0
4,19431,153871302,-;Code: 6c 0f 82 24 01 00 00 48 01 93 c0 00 00 00 e9 52 f5 ff ff 48 89 df 4d 89 f5 e8 e7 b4 fd ff e9 c9 fd ff ff 4c 8d 88 d0 00 00 00 <48> 8b 80 d0 00 00 00 4c 8d 78 c8 49 39 c1 0f 84 6c fa ff ff 44 88
4,19432,153871306,-;RSP: 0018:ffffd13040184c98 EFLAGS: 00010286
4,19433,153871311,-;RAX: 0000000000000000 RBX: ffff8d64683f8900 RCX: 0000000000000000
4,19434,153871314,-;RDX: 0000000000000000 RSI: 0000000000000000 RDI: 0000000000000000
4,19435,153871317,-;RBP: ffffd13040184da8 R08: 0000000000000200 R09: 00000000000000d0
4,19436,153871374,-;R10: 0000000000000000 R11: 0000000000000000 R12: ffff8d64681b3540
4,19437,153871377,-;R13: 0000000000000000 R14: 0000000000000200 R15: ffff8d6459d170d0
4,19438,153871381,-;FS:  0000000000000000(0000) GS:ffff8d65f5a3b000(0000) knlGS:0000000000000000
4,19439,153871385,-;CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
4,19440,153871388,-;CR2: 00000000000000d0 CR3: 00000001a5440002 CR4: 00000000001726f0
0,19441,153871391,-;Kernel panic - not syncing: Fatal exception in interrupt
0,19442,153871407,-;Kernel Offset: 0x16000000 from 0xffffffff81000000 (relocation range: 0xffffffff80000000-0xffffffffbfffffff)
0,19443,153951562,-;Rebooting in 30 seconds..