Re: sys_pselect assertion "timo || _kernel_lock_held()" failed
On Tue, Feb 14, 2023 at 08:05:37AM +0100, Mark Kettenis wrote: > > Date: Tue, 14 Feb 2023 07:25:18 +0100 > > From: Anton Lindqvist > > > > On Tue, Feb 14, 2023 at 01:08:54AM +0100, Alexander Bluhm wrote: > > > Hi, > > > > > > Today I saw this panic on my i386 regress machine. > > > > > > panic: kernel diagnostic assertion "timo || _kernel_lock_held()" failed: > > > file "/usr/src/sys/kern/kern_synch.c", line 127 > > > > Same here on my amd64 and arm64 machines. Was the poll/select unlock > > ever tested beyond compile-time? > > Clearly not. Please back it out. > Sure I tested it. But missing the null timeout case. Sorry for this. I backed out this tiff.
Re: sys_pselect assertion "timo || _kernel_lock_held()" failed
It needs to be fixed in the next 8 hours, or it should be backed out.
Re: sys_pselect assertion "timo || _kernel_lock_held()" failed
> Date: Tue, 14 Feb 2023 07:25:18 +0100
> From: Anton Lindqvist
>
> On Tue, Feb 14, 2023 at 01:08:54AM +0100, Alexander Bluhm wrote:
> > Hi,
> >
> > Today I saw this panic on my i386 regress machine.
> >
> > panic: kernel diagnostic assertion "timo || _kernel_lock_held()" failed:
> > file "/usr/src/sys/kern/kern_synch.c", line 127
>
> Same here on my amd64 and arm64 machines. Was the poll/select unlock
> ever tested beyond compile-time?
Clearly not. Please back it out.
> > Looks like src/regress/lib/libc/sys/ triggered it. Kernel was built
> > from some 2023-02-13 source checkout. I will keep watching if it
> > happens again.
> >
> > run-t_select
> > cc -O2 -pipe -std=gnu99 -MD -MP -c
> > /usr/src/regress/lib/libc/sys/t_select.c
> > cc -o t_select t_select.o atf-c.o
> > ulimit -c unlimited && ntests="`./t_select -n`" && echo "1..$ntests" &&
> > tnumbers="`jot -ns' ' - 1 $ntests`" && make -C
> > /usr/src/regress/lib/libc/sys PROG=t_select NUMBERS="$tnumbers" regress
> > 1..2
> > run-t_select-1
> > 1 Checks pselect's temporary mask setting when a signal is received (PR
> > lib/43625)
> > ./t_select -r 1
> > Timeout, server ot4 not responding.
> >
> > panic: kernel diagnostic assertion "timo || _kernel_lock_held()" failed:
> > file "/usr/src/sys/kern/kern_synch.c", line 127
> > Stopped at db_enter+0x4: popl%ebp
> > TIDPIDUID PRFLAGS PFLAGS CPU COMMAND
> > *494368 36805 0 00x89 t_select
> > 223467 53838 0 0x14000 0x42000 softclock
> > db_enter() at db_enter+0x4
> > panic(d0c60cae) at panic+0x7a
> > __assert(d0cccada,d0c6daa7,7f,d0ce58fd) at __assert+0x19
> > tsleep(d0fcefd0,118,d0d0cf14,0) at tsleep+0x117
> > tsleep_nsec(d0fcefd0,118,d0d0cf14,) at tsleep_nsec+0xcc
> > dopselect(d621da8c,1,cf7db3f8,0,0,0,f5b0ab74,f5b0abc8) at dopselect+0x49c
> > sys_pselect(d621da8c,f5b0abd0,f5b0abc8) at sys_pselect+0xa9
> > syscall(f5b0ac10) at syscall+0x301
> > Xsyscall_untramp() at Xsyscall_untramp+0xa9
> > end of kernel
> > https://www.openbsd.org/ddb.html describes the minimum info required in bug
> > reports. Insufficient info makes it difficult to find and fix bugs.
> >
> > ddb{9}> show panic
> > *cpu9: kernel diagnostic assertion "timo || _kernel_lock_held()" failed:
> > file "/usr/src/sys/kern/kern_synch.c", line 127
> >
> > ddb{9}> trace
> > db_enter() at db_enter+0x4
> > panic(d0c60cae) at panic+0x7a
> > __assert(d0cccada,d0c6daa7,7f,d0ce58fd) at __assert+0x19
> > tsleep(d0fcefd0,118,d0d0cf14,0) at tsleep+0x117
> > tsleep_nsec(d0fcefd0,118,d0d0cf14,) at tsleep_nsec+0xcc
> > dopselect(d621da8c,1,cf7db3f8,0,0,0,f5b0ab74,f5b0abc8) at dopselect+0x49c
> > sys_pselect(d621da8c,f5b0abd0,f5b0abc8) at sys_pselect+0xa9
> > syscall(f5b0ac10) at syscall+0x301
> > Xsyscall_untramp() at Xsyscall_untramp+0xa9
> > end of kernel
> >
> > ddb{9}> ps
> >PID TID PPIDUID S FLAGS WAIT COMMAND
> > *36805 494368 81530 0 7 0x8t_select
> > 81530 403270 40998 0 30x82 nanoslp t_select
> > 40998 94085 15069 0 30x10008a sigsusp make
> > 15069 146328 39109 0 30x10008a sigsusp sh
> > 39109 344737 51331 0 30x10008a sigsusp make
> > 51331 138704 34007 0 30x10008a sigsusp sh
> > 34007 93629 19868 0 30x10008a sigsusp make
> > 19868 317272 38049 0 30x10008a sigsusp sh
> > 38049 440823 5232 0 30x10008a sigsusp make
> > 37773 470707 5644 0 30x100082 piperdgzip
> > 5644 31299 5232 0 30x100082 piperdpax
> > 5232 392807 48080 0 30x82 piperdperl
> > 48080 317705 5394 0 30x10008a sigsusp ksh
> > 5394 64950 41772 0 30x9a kqreadsshd
> > 21685 469765 1 0 30x100083 ttyin getty
> > 54886 396067 1 0 30x100083 ttyin getty
> > 30334 46910 1 0 30x100083 ttyin getty
> > 32613 460954 1 0 30x100083 ttyin getty
> > 98276 290762 1 0 30x100083 ttyin getty
> > 83393 276624 1 0 30x100083 ttyin getty
> > 58262 416339 1 0 30x100098 kqreadcron
> > 63115 378072 1 99 3 0x1100090 kqreadsndiod
> > 16973 434562 1110 30x100090 kqreadsndiod
> > 31914 352102 1 0 30x100090 kqreadinetd
> > 29012 259544 75755 95 3 0x1100092 kqreadsmtpd
> > 75423 90965 75755103 3 0x1100092 kqreadsmtpd
> > 21079 436365 75755 95 3 0x1100092 kqreadsmtpd
> > 50673 244082 75755 95 30x100092 kqreadsmtpd
> > 29210 305613 75755 95 3 0x1100092 kqreadsmtpd
> > 23149
Re: sys_pselect assertion "timo || _kernel_lock_held()" failed
On Tue, Feb 14, 2023 at 01:08:54AM +0100, Alexander Bluhm wrote:
> Hi,
>
> Today I saw this panic on my i386 regress machine.
>
> panic: kernel diagnostic assertion "timo || _kernel_lock_held()" failed: file
> "/usr/src/sys/kern/kern_synch.c", line 127
Same here on my amd64 and arm64 machines. Was the poll/select unlock
ever tested beyond compile-time?
> Looks like src/regress/lib/libc/sys/ triggered it. Kernel was built
> from some 2023-02-13 source checkout. I will keep watching if it
> happens again.
>
> run-t_select
> cc -O2 -pipe -std=gnu99 -MD -MP -c /usr/src/regress/lib/libc/sys/t_select.c
> cc -o t_select t_select.o atf-c.o
> ulimit -c unlimited && ntests="`./t_select -n`" && echo "1..$ntests" &&
> tnumbers="`jot -ns' ' - 1 $ntests`" && make -C /usr/src/regress/lib/libc/sys
> PROG=t_select NUMBERS="$tnumbers" regress
> 1..2
> run-t_select-1
> 1 Checks pselect's temporary mask setting when a signal is received (PR
> lib/43625)
> ./t_select -r 1
> Timeout, server ot4 not responding.
>
> panic: kernel diagnostic assertion "timo || _kernel_lock_held()" failed: file
> "/usr/src/sys/kern/kern_synch.c", line 127
> Stopped at db_enter+0x4: popl%ebp
> TIDPIDUID PRFLAGS PFLAGS CPU COMMAND
> *494368 36805 0 00x89 t_select
> 223467 53838 0 0x14000 0x42000 softclock
> db_enter() at db_enter+0x4
> panic(d0c60cae) at panic+0x7a
> __assert(d0cccada,d0c6daa7,7f,d0ce58fd) at __assert+0x19
> tsleep(d0fcefd0,118,d0d0cf14,0) at tsleep+0x117
> tsleep_nsec(d0fcefd0,118,d0d0cf14,) at tsleep_nsec+0xcc
> dopselect(d621da8c,1,cf7db3f8,0,0,0,f5b0ab74,f5b0abc8) at dopselect+0x49c
> sys_pselect(d621da8c,f5b0abd0,f5b0abc8) at sys_pselect+0xa9
> syscall(f5b0ac10) at syscall+0x301
> Xsyscall_untramp() at Xsyscall_untramp+0xa9
> end of kernel
> https://www.openbsd.org/ddb.html describes the minimum info required in bug
> reports. Insufficient info makes it difficult to find and fix bugs.
>
> ddb{9}> show panic
> *cpu9: kernel diagnostic assertion "timo || _kernel_lock_held()" failed: file
> "/usr/src/sys/kern/kern_synch.c", line 127
>
> ddb{9}> trace
> db_enter() at db_enter+0x4
> panic(d0c60cae) at panic+0x7a
> __assert(d0cccada,d0c6daa7,7f,d0ce58fd) at __assert+0x19
> tsleep(d0fcefd0,118,d0d0cf14,0) at tsleep+0x117
> tsleep_nsec(d0fcefd0,118,d0d0cf14,) at tsleep_nsec+0xcc
> dopselect(d621da8c,1,cf7db3f8,0,0,0,f5b0ab74,f5b0abc8) at dopselect+0x49c
> sys_pselect(d621da8c,f5b0abd0,f5b0abc8) at sys_pselect+0xa9
> syscall(f5b0ac10) at syscall+0x301
> Xsyscall_untramp() at Xsyscall_untramp+0xa9
> end of kernel
>
> ddb{9}> ps
>PID TID PPIDUID S FLAGS WAIT COMMAND
> *36805 494368 81530 0 7 0x8t_select
> 81530 403270 40998 0 30x82 nanoslp t_select
> 40998 94085 15069 0 30x10008a sigsusp make
> 15069 146328 39109 0 30x10008a sigsusp sh
> 39109 344737 51331 0 30x10008a sigsusp make
> 51331 138704 34007 0 30x10008a sigsusp sh
> 34007 93629 19868 0 30x10008a sigsusp make
> 19868 317272 38049 0 30x10008a sigsusp sh
> 38049 440823 5232 0 30x10008a sigsusp make
> 37773 470707 5644 0 30x100082 piperdgzip
> 5644 31299 5232 0 30x100082 piperdpax
> 5232 392807 48080 0 30x82 piperdperl
> 48080 317705 5394 0 30x10008a sigsusp ksh
> 5394 64950 41772 0 30x9a kqreadsshd
> 21685 469765 1 0 30x100083 ttyin getty
> 54886 396067 1 0 30x100083 ttyin getty
> 30334 46910 1 0 30x100083 ttyin getty
> 32613 460954 1 0 30x100083 ttyin getty
> 98276 290762 1 0 30x100083 ttyin getty
> 83393 276624 1 0 30x100083 ttyin getty
> 58262 416339 1 0 30x100098 kqreadcron
> 63115 378072 1 99 3 0x1100090 kqreadsndiod
> 16973 434562 1110 30x100090 kqreadsndiod
> 31914 352102 1 0 30x100090 kqreadinetd
> 29012 259544 75755 95 3 0x1100092 kqreadsmtpd
> 75423 90965 75755103 3 0x1100092 kqreadsmtpd
> 21079 436365 75755 95 3 0x1100092 kqreadsmtpd
> 50673 244082 75755 95 30x100092 kqreadsmtpd
> 29210 305613 75755 95 3 0x1100092 kqreadsmtpd
> 23149 255222 75755 95 3 0x1100092 kqreadsmtpd
> 75755 17291 1 0 30x100080 kqreadsmtpd
> 93529 264256 66818 91 30x92 kqreadsnmpd_metrics
> 66818 486393 1 0 30x100080 kqreadsnmpd
> 44889 252400 1 91 3
sys_pselect assertion "timo || _kernel_lock_held()" failed
Hi,
Today I saw this panic on my i386 regress machine.
panic: kernel diagnostic assertion "timo || _kernel_lock_held()" failed: file
"/usr/src/sys/kern/kern_synch.c", line 127
Looks like src/regress/lib/libc/sys/ triggered it. Kernel was built
from some 2023-02-13 source checkout. I will keep watching if it
happens again.
run-t_select
cc -O2 -pipe -std=gnu99 -MD -MP -c /usr/src/regress/lib/libc/sys/t_select.c
cc -o t_select t_select.o atf-c.o
ulimit -c unlimited && ntests="`./t_select -n`" && echo "1..$ntests" &&
tnumbers="`jot -ns' ' - 1 $ntests`" && make -C /usr/src/regress/lib/libc/sys
PROG=t_select NUMBERS="$tnumbers" regress
1..2
run-t_select-1
1 Checks pselect's temporary mask setting when a signal is received (PR
lib/43625)
./t_select -r 1
Timeout, server ot4 not responding.
panic: kernel diagnostic assertion "timo || _kernel_lock_held()" failed: file
"/usr/src/sys/kern/kern_synch.c", line 127
Stopped at db_enter+0x4: popl%ebp
TIDPIDUID PRFLAGS PFLAGS CPU COMMAND
*494368 36805 0 00x89 t_select
223467 53838 0 0x14000 0x42000 softclock
db_enter() at db_enter+0x4
panic(d0c60cae) at panic+0x7a
__assert(d0cccada,d0c6daa7,7f,d0ce58fd) at __assert+0x19
tsleep(d0fcefd0,118,d0d0cf14,0) at tsleep+0x117
tsleep_nsec(d0fcefd0,118,d0d0cf14,) at tsleep_nsec+0xcc
dopselect(d621da8c,1,cf7db3f8,0,0,0,f5b0ab74,f5b0abc8) at dopselect+0x49c
sys_pselect(d621da8c,f5b0abd0,f5b0abc8) at sys_pselect+0xa9
syscall(f5b0ac10) at syscall+0x301
Xsyscall_untramp() at Xsyscall_untramp+0xa9
end of kernel
https://www.openbsd.org/ddb.html describes the minimum info required in bug
reports. Insufficient info makes it difficult to find and fix bugs.
ddb{9}> show panic
*cpu9: kernel diagnostic assertion "timo || _kernel_lock_held()" failed: file
"/usr/src/sys/kern/kern_synch.c", line 127
ddb{9}> trace
db_enter() at db_enter+0x4
panic(d0c60cae) at panic+0x7a
__assert(d0cccada,d0c6daa7,7f,d0ce58fd) at __assert+0x19
tsleep(d0fcefd0,118,d0d0cf14,0) at tsleep+0x117
tsleep_nsec(d0fcefd0,118,d0d0cf14,) at tsleep_nsec+0xcc
dopselect(d621da8c,1,cf7db3f8,0,0,0,f5b0ab74,f5b0abc8) at dopselect+0x49c
sys_pselect(d621da8c,f5b0abd0,f5b0abc8) at sys_pselect+0xa9
syscall(f5b0ac10) at syscall+0x301
Xsyscall_untramp() at Xsyscall_untramp+0xa9
end of kernel
ddb{9}> ps
PID TID PPIDUID S FLAGS WAIT COMMAND
*36805 494368 81530 0 7 0x8t_select
81530 403270 40998 0 30x82 nanoslp t_select
40998 94085 15069 0 30x10008a sigsusp make
15069 146328 39109 0 30x10008a sigsusp sh
39109 344737 51331 0 30x10008a sigsusp make
51331 138704 34007 0 30x10008a sigsusp sh
34007 93629 19868 0 30x10008a sigsusp make
19868 317272 38049 0 30x10008a sigsusp sh
38049 440823 5232 0 30x10008a sigsusp make
37773 470707 5644 0 30x100082 piperdgzip
5644 31299 5232 0 30x100082 piperdpax
5232 392807 48080 0 30x82 piperdperl
48080 317705 5394 0 30x10008a sigsusp ksh
5394 64950 41772 0 30x9a kqreadsshd
21685 469765 1 0 30x100083 ttyin getty
54886 396067 1 0 30x100083 ttyin getty
30334 46910 1 0 30x100083 ttyin getty
32613 460954 1 0 30x100083 ttyin getty
98276 290762 1 0 30x100083 ttyin getty
83393 276624 1 0 30x100083 ttyin getty
58262 416339 1 0 30x100098 kqreadcron
63115 378072 1 99 3 0x1100090 kqreadsndiod
16973 434562 1110 30x100090 kqreadsndiod
31914 352102 1 0 30x100090 kqreadinetd
29012 259544 75755 95 3 0x1100092 kqreadsmtpd
75423 90965 75755103 3 0x1100092 kqreadsmtpd
21079 436365 75755 95 3 0x1100092 kqreadsmtpd
50673 244082 75755 95 30x100092 kqreadsmtpd
29210 305613 75755 95 3 0x1100092 kqreadsmtpd
23149 255222 75755 95 3 0x1100092 kqreadsmtpd
75755 17291 1 0 30x100080 kqreadsmtpd
93529 264256 66818 91 30x92 kqreadsnmpd_metrics
66818 486393 1 0 30x100080 kqreadsnmpd
44889 252400 1 91 3 0x1100092 kqreadsnmpd
41772 245133 1 0 30x88 kqreadsshd
66620 411509 0 0 3 0x14280 nfsidlnfsio
80915 345110 0 0 3 0x14280 nfsidlnfsio
10608 431262 0 0 3 0x14280 nfsidlnfsio
11489 201187 0 0 3 0x14280 nfsidlnfsio
