Comment 1 Mark Johnston 2024-01-12 18:28:23 UTC

I presume the crash happened only the one time?  It looks like there's some race condition between cdregister() and cddone().

Comment 2 Warner Losh 2024-01-12 18:42:13 UTC

It would be nice to get a traceback of all the threads to see what it might be racing...

(In reply to Mark Johnston from comment #1)

Yes, this was the only time the crash happened.

Created attachment 247608 [details]
threads from vmcore file

Comment 5 Warner Losh 2024-01-13 04:45:43 UTC

So it looks like cddone is releasing the ccb. As part of that we drop the last reference to the cd and wind up calling cdcleanup.

I'm not sure why we drop the last reference inside the callback to cddone though. That's unexpected...

Comment 6 Warner Losh 2024-01-13 04:46:52 UTC

oh, wait, we do expect to drop the last reference in cddone.

Comment 7 Mark Johnston 2024-01-15 19:13:23 UTC

(In reply to Andreas Bock from comment #4)
If possible, it would also be useful to see output from the following commands:

(kgdb) tid 100311
(kgdb) bt
(kgdb) tid 100242
(kgdb) bt

(In reply to Mark Johnston from comment #7)

(kgdb) tid 100311
(kgdb) bt
#0  cpustop_handler () at /usr/src/sys/x86/x86/mp_x86.c:1519
#1  0xffffffff80a8c2f9 in ipi_nmi_handler () at /usr/src/sys/x86/x86/mp_x86.c:1476
#2  0xffffffff80abf38f in trap (frame=0xfffffe01d2a16f30) at /usr/src/sys/amd64/amd64/trap.c:238
#3  <signal handler called>
#4  lock_delay (la=la@entry=0xfffffe02ca92cc50) at /usr/src/sys/kern/subr_lock.c:140
#5  0xffffffff8073daf8 in __mtx_lock_sleep (c=0xfffff83049fc14e8, v=<optimized out>) at /usr/src/sys/kern/kern_mutex.c:604
#6  0xffffffff80300e2d in xptdevicetraverse (target=<optimized out>, start_device=<optimized out>, tr_func=0xffffffff80302120 <xpt_async_process_dev>, arg=0xfffff810492aa000)
    at /usr/src/sys/cam/cam_xpt.c:2295
#7  0xffffffff80300aba in xpttargettraverse (bus=bus@entry=0xfffff80102dbaf00, start_target=start_target@entry=0x0, tr_func=0xffffffff803020c0 <xpt_async_process_tgt>, arg=0x800, 
    arg@entry=0xfffff810492aa000) at /usr/src/sys/cam/cam_xpt.c:2257
#8  0xffffffff802fda6d in xpt_async_process (periph=<optimized out>, ccb=0xfffff810492aa000) at /usr/src/sys/cam/cam_xpt.c:4295
#9  0xffffffff802fe193 in xpt_done_process (ccb_h=0xfffff810492aa000) at /usr/src/sys/cam/cam_xpt.c:5435
#10 0xffffffff803000a5 in xpt_done_td (arg=arg@entry=0xffffffff80f3f100 <cam_doneqs>) at /usr/src/sys/cam/cam_xpt.c:5462
#11 0xffffffff8071e1de in fork_exit (callout=0xffffffff802fffb0 <xpt_done_td>, arg=0xffffffff80f3f100 <cam_doneqs>, frame=0xfffffe02ca92cf40) at /usr/src/sys/kern/kern_fork.c:1093
#12 <signal handler called>


(kgdb) tid 100242
(kgdb) bt
#0  cpustop_handler () at /usr/src/sys/x86/x86/mp_x86.c:1519
#1  0xffffffff80a8c2f9 in ipi_nmi_handler () at /usr/src/sys/x86/x86/mp_x86.c:1476
#2  0xffffffff80abf38f in trap (frame=0xfffffe01a2a1bf30) at /usr/src/sys/amd64/amd64/trap.c:238
#3  <signal handler called>
#4  lock_delay (la=la@entry=0xfffffe02ca7b3430) at /usr/src/sys/kern/subr_lock.c:140
#5  0xffffffff8073e011 in _mtx_lock_spin_cookie (c=0xffffffff810f4e38 <cnputs_mtx+24>, v=<optimized out>) at /usr/src/sys/kern/kern_mutex.c:775
#6  0xffffffff806f8ea8 in cnputsn (p=0xfffffe02ca7b36a0 "(cd0:ahcich0:0:0:0): Periph destroyed\n", p@entry=0x5 <error: Cannot access memory at address 0x5>, n=38)
    at /usr/src/sys/kern/kern_cons.c:551
#7  0xffffffff806f8dcf in cnputs (p=0xfffffe02ca7b3430 "\030\020\340\200\377\377\377\377", p@entry=0xfffffe02ca7b36a0 "(cd0:ahcich0:0:0:0): Periph destroyed\n")
    at /usr/src/sys/kern/kern_cons.c:565
#8  0xffffffff807b4faa in prf_putbuf (bufr=0xfffffe02ca7b36a0 "(cd0:ahcich0:0:0:0): Periph destroyed\n", flags=5, pri=<optimized out>) at /usr/src/sys/kern/subr_prf.c:451
#9  putbuf (c=<optimized out>, ap=0xfffffe02ca7b3670) at /usr/src/sys/kern/subr_prf.c:471
#10 putchar (c=<optimized out>, arg=0xfffffe02ca7b3670) at /usr/src/sys/kern/subr_prf.c:514
#11 0xffffffff807b4b4c in kvprintf (fmt=0xffffffff80b08c6c "", func=0x4000, arg=arg@entry=0xfffffe02ca7b3670, radix=radix@entry=10, ap=ap@entry=0xfffffe02ca7b3790)
    at /usr/src/sys/kern/subr_prf.c:845
#12 0xffffffff807b549c in _vprintf (level=level@entry=-1, flags=flags@entry=5, fmt=0x2d4 <error: Cannot access memory at address 0x2d4>, ap=0xfefefefefefefeff, ap@entry=0xfffffe02ca7b3790)
    at /usr/src/sys/kern/subr_prf.c:296
#13 0xffffffff807b5703 in vprintf (fmt=0x2d4 <error: Cannot access memory at address 0x2d4>, ap=0xfffffe02ca7b3790) at /usr/src/sys/kern/subr_prf.c:414
#14 printf (fmt=0x2d4 <error: Cannot access memory at address 0x2d4>) at /usr/src/sys/kern/subr_prf.c:403
#15 0xffffffff802f85f2 in xpt_print (path=0xfffff8184919d7c0, fmt=0xffffffff80aff26d "Periph destroyed\n") at /usr/src/sys/cam/cam_xpt.c:3829
#16 0xffffffff802f4cae in camperiphfree (periph=0xfffff8184918a500) at /usr/src/sys/cam/cam_periph.c:757
#17 cam_periph_release_locked_buses (periph=periph@entry=0xfffff8184918a500) at /usr/src/sys/cam/cam_periph.c:448
#18 0xffffffff802f4e87 in cam_periph_release_locked (periph=0xfffff8184918a500) at /usr/src/sys/cam/cam_periph.c:459
#19 cam_periph_release (periph=0xfffff8184918a500) at /usr/src/sys/cam/cam_periph.c:474
#20 0xffffffff8069f067 in g_disk_providergone (pp=0xfffff808495fd600) at /usr/src/sys/geom/geom_disk.c:791
#21 0xffffffff806a4f50 in g_destroy_provider (pp=pp@entry=0xfffff808495fd600) at /usr/src/sys/geom/geom_subr.c:812
#22 0xffffffff806a0605 in g_orphan_register (pp=0xfffff808495fd600) at /usr/src/sys/geom/geom_event.c:206
#23 one_event () at /usr/src/sys/geom/geom_event.c:231
#24 g_run_events () at /usr/src/sys/geom/geom_event.c:266
#25 0xffffffff8071e1de in fork_exit (callout=0xffffffff806a2b10 <g_event_procbody>, arg=0x0, frame=0xfffffe02ca7b3f40) at /usr/src/sys/kern/kern_fork.c:1093
#26 <signal handler called>

Comment 9 Mark Johnston 2024-01-15 21:55:01 UTC

(In reply to Andreas Bock from comment #8)
Thanks.  So it appears that two threads raced to free the same periph.  cam_periph_release_locked_buses() only calls camperiphfree() when the periph refcount drops to zero, so presumably something is going wrong with the refcounting.  Unfortunately, since this was a release kernel, INVARIANTS wasn't on, so it's harder to say where things started to go off the rails.  Maybe some of the CAM experts can comment further.

Comment 10 Warner Losh 2024-01-15 22:59:54 UTC

I fixed a similar bug in da a while afho. Let me see if i can find it.

Comment 11 Warner Losh 2024-01-15 23:50:39 UTC

That bug may have been 02fa548cde3215113a7004f60bf8597a8a7d50cd... 

The tl;dr on the bug is that we carefully single step during the device probe. There are times, though, when we poll the device. These two things can race and can lead to either abandoned I/O or extra I/Os being processes (I/O here should be read as cam ccb processing).

This could be a race in cd too. We start the media polling timeout in cdregister, just after we create the disk.

But unlike da, cd makes sure that we are in state CD_STATE_NORMAL before we set tur = true and do a xpt_schedule().

But there's a fair number of xpt_schedule() that happen, maybe in CD_STATE_MEDIA_SIZE and/or cdcheckmedia? Or maybe in response to AC_SCSI_AEN from AHCI?

It's unclear to me right now which of these are happening, if any. The schedule would cause more threads to run at the same time, perhaps, leading to this situation?

I chased this bug in da for years until I could find this was the race I was looking for.

Comment 12 Mark Johnston 2024-01-16 15:04:25 UTC

(In reply to Warner Losh from comment #11)
Should cam_periph_acquire() assert that the refcount >= 1, like cam_periph_doacquire()?

If the problem is related to bad SATA connectors, it's probably not very reproducible, but if it is, it would be useful to try and reproduce this with INVARIANTS enabled.

Comment 13 Warner Losh 2024-01-17 16:47:33 UTC

(In reply to Mark Johnston from comment #12)
It might be good to add. I added a number of 'obvious' asserts and couldn't get a stable system. This may have been one of them, or maybe I just overlooked it.

If it is what I think it might be (and that's speculative), then the problem is the second thread doing the media checking (or a second thread (ahci sim I think) sending an async event that's intermingled with 'probe' phase of the cd). In that case, the reference counting might not help (or be too late to help). Though the NORMAL tests suggests that this may be a false trail.

If this is at all reproducible, I'd add printf in the `case AC_SCSI_AEN:` that calls xpt_schedule (though the test for NORMAL should mean it is safe). I'd add one in the call in cdmediapoll as well (though the same caveat applies to NORMAL). If they do print just before the crash, that suggests the 'should be safe' is wrong for a reason we need to look at more.

Comment 14 Mark Johnston 2024-01-20 18:52:31 UTC

Looking at this for a bit with a fresh set of eyes...

We destroyed the periph twice.  Once, via the GEOM "disk gone" callback, cddiskgonecb(), which just releases a periph reference.  That reference is acquired when disk_create() is called, which happens when the periph enters the NORMAL state.

The second destruction happened when releasing a transient reference while handling the CD_CCB_MEDIA_ALLOW/PREVENT case in cddone().  So, we must have entered the NORMAL state and then entered one of the CD_STATE_MEDIA_PREVENT/ALLOW states.  Where do we enter these states?

CD_STATE_MEDIA_ALLOW is entered after we successfully query the media size, while in state CD_STATE_MEDIA_SIZE.  We can only enter that state while in one of CD_STATE_MEDIA_PREVENT/ALLOW, so we must have been in CD_STATE_MEDIA_PREVENT.

We enter CD_STATE_MEDIA_PREVENT from cdcheckmedia(), which can operate synchronously or not.  The synchronous calls are protected by cam_periph_hold().  The asynchronous case comes from cdstrategy().  And, lo and behold, it does not acquire a periph reference, so nothing is preventing the periph from going away while executing this sub-portion of the cd state machine.  I think.

The async case was added here https://cgit.freebsd.org/src/commit/?id=dd78f43259efd551f76a6cb7744bce49c215863e

Comment 15 Mark Johnston 2024-01-20 18:54:45 UTC

https://reviews.freebsd.org/D43525 is a possible fix.  Someone who knows CAM better than me should verify that my theory actually makes sense.

Comment 16 Warner Losh 2024-01-21 04:33:55 UTC

Normally, cdstrategy only gets called after cdopen and cdclose won't get called until the I/O is complete.

However, cdstrategy queues the I/O and calls cdmediacheck. If the drive is invalidated while that's running, we'll fail all the queued I/O, triggering cdclose which drops that reference.

So for the async case, we need another periph_acquire / release pair to cope with this. I think we only need it from cdstrategy (the only async case). The other places we call it are covered by other acquired references (though always acquiring it and dropping it wouldn't hurt and might help if my analysis of the synchronous cases is incorrect somehow). But I think it's a property of the cdstrategy context needing a reference to do extra things, rather than it being checked asynchronously.

Other comments I've left in the review.

Comment 17 commit-hook 2024-01-30 14:32:01 UTC

A commit in branch main references this bug:

URL: https://cgit.FreeBSD.org/src/commit/?id=c961afe82596bdeb7e6a8626f02ddb181c8a24b6

commit c961afe82596bdeb7e6a8626f02ddb181c8a24b6
Author:     Mark Johnston <markj@FreeBSD.org>
AuthorDate: 2024-01-30 01:01:12 +0000
Commit:     Mark Johnston <markj@FreeBSD.org>
CommitDate: 2024-01-30 14:24:55 +0000

    scsi_cd: Maintain a periph reference during media checks

    Otherwise nothing prevents the asynchronous media check state machine
    from running after the periph has been destroyed, which can result in a
    double free.  Acquire the reference even when performing a synchronous
    check, since that doesn't hurt and keeps things simpler.

    PR:             276251
    Reviewed by:    imp
    Fixes:          dd78f43259ef ("scsi_cd: make the media check asynchronous")
    MFC after:      1 week
    Differential Revision:  https://reviews.freebsd.org/D43525

 sys/cam/scsi/scsi_cd.c | 21 ++++++++++-----------
 1 file changed, 10 insertions(+), 11 deletions(-)

Comment 18 commit-hook 2024-02-09 15:05:08 UTC

A commit in branch stable/14 references this bug:

URL: https://cgit.FreeBSD.org/src/commit/?id=212af7b6133a60382e62237bb3e99cf63342d157

commit 212af7b6133a60382e62237bb3e99cf63342d157
Author:     Mark Johnston <markj@FreeBSD.org>
AuthorDate: 2024-01-30 01:01:12 +0000
Commit:     Mark Johnston <markj@FreeBSD.org>
CommitDate: 2024-02-09 14:55:45 +0000

    scsi_cd: Maintain a periph reference during media checks

    Otherwise nothing prevents the asynchronous media check state machine
    from running after the periph has been destroyed, which can result in a
    double free.  Acquire the reference even when performing a synchronous
    check, since that doesn't hurt and keeps things simpler.

    PR:             276251
    Reviewed by:    imp
    Fixes:          dd78f43259ef ("scsi_cd: make the media check asynchronous")
    MFC after:      1 week
    Differential Revision:  https://reviews.freebsd.org/D43525

    (cherry picked from commit c961afe82596bdeb7e6a8626f02ddb181c8a24b6)

 sys/cam/scsi/scsi_cd.c | 21 ++++++++++-----------
 1 file changed, 10 insertions(+), 11 deletions(-)

Comment 19 Mark Johnston 2024-02-09 15:42:11 UTC

I believe this is fixed now.  Thank you for the report.

Comment 20 commit-hook 2024-02-09 15:42:23 UTC

A commit in branch stable/13 references this bug:

URL: https://cgit.FreeBSD.org/src/commit/?id=979e15bbf0cb35d6ef0b329507b2ef9507cfc6eb

commit 979e15bbf0cb35d6ef0b329507b2ef9507cfc6eb
Author:     Mark Johnston <markj@FreeBSD.org>
AuthorDate: 2024-01-30 01:01:12 +0000
Commit:     Mark Johnston <markj@FreeBSD.org>
CommitDate: 2024-02-09 15:38:19 +0000

    scsi_cd: Maintain a periph reference during media checks

    Otherwise nothing prevents the asynchronous media check state machine
    from running after the periph has been destroyed, which can result in a
    double free.  Acquire the reference even when performing a synchronous
    check, since that doesn't hurt and keeps things simpler.

    PR:             276251
    Reviewed by:    imp
    Fixes:          dd78f43259ef ("scsi_cd: make the media check asynchronous")
    MFC after:      1 week
    Differential Revision:  https://reviews.freebsd.org/D43525

    (cherry picked from commit c961afe82596bdeb7e6a8626f02ddb181c8a24b6)

 sys/cam/scsi/scsi_cd.c | 21 ++++++++++-----------
 1 file changed, 10 insertions(+), 11 deletions(-)