nvme: nvme0: Device not ready; aborting shutdown, CSTS=0x5

[dkwo]

After some i/o intensive operation (e.g. building the Linux kernel), the nvme prevents shutdown or sleep, after which the system becomes unresponsive. It is hard to capture logs, since this affects the nvme. Note that the reboot causes an increment of the unsafe_shutdowns count, as seen by nvme smart-log.

A developer for asahi on Alpine Linux (mps in irc) was able to capture logs for the sleep case:

[144958.031443] macsmc-rtkit 290400000.smc: RTKit: syslog message: apComms.cpp:354: SMC HID Event: 01 06 01
[144958.032133] PM: suspend entry (s2idle)
[144958.032931] Filesystems sync: 0.000 seconds
[144958.046586] Freezing user space processes
[144958.050355] Freezing user space processes completed (elapsed 0.003 seconds)
[144958.050364] OOM killer disabled.
[144958.050366] Freezing remaining freezable tasks
[144958.051621] Freezing remaining freezable tasks completed (elapsed 0.001 seconds)
[144958.051626] printk: Suspending console(s) (use no_console_suspend to debug)
[144958.141588] apple-dcp 289c00000.dcp: dcp_dptx_disconnect(port=0)
[144958.142016] apple-dcp 38bc00000.dcp: RTKit: syslog message: BrightnessLCD.cpp:803: [AFK]nitsToDBV: iDAC out of range
[144958.231030] macsmc-rtkit 290400000.smc: RTKit: syslog message: apComms.cpp:354: SMC HID Event: 01 06 00
[144959.150712] nvme-apple 393cc0000.nvme: RTKit: syslog message: cmd.c:8254: NVMe shutdown start seg->lba: 0, seg->size: 0
[144964.152845] nvme nvme0: Device not ready; aborting shutdown, CSTS=0x5
[144978.697972] nvme-apple 393cc0000.nvme: RTKit: syslog message: cmd.c:750: Oldest tag 501 is 19 seconds VERY OLD with cmdQe:10
[144979.697914] nvme-apple 393cc0000.nvme: RTKit: syslog message: cmd.c:754: Oldest tag is about to crash!!
[144980.697931] nvme-apple 393cc0000.nvme: RTKit: syslog message: cmd.c:742: Oldest high water mark moved up to 21,tag 501, cmdQ CQ_IMMED
[144981.697945] nvme-apple 393cc0000.nvme: RTKit: syslog message: cmd.c:742: Oldest high water mark moved up to 22,tag 501, cmdQ CQ_IMMED
[144982.697970] nvme-apple 393cc0000.nvme: RTKit: syslog message: cmd.c:742: Oldest high water mark moved up to 23,tag 501, cmdQ CQ_IMMED
[144983.697912] nvme-apple 393cc0000.nvme: RTKit: syslog message: cmd.c:742: Oldest high water mark moved up to 24,tag 501, cmdQ CQ_IMMED
[144984.697938] nvme-apple 393cc0000.nvme: RTKit: syslog message: cmd.c:742: Oldest high water mark moved up to 25,tag 501, cmdQ CQ_IMMED
[144985.697976] nvme-apple 393cc0000.nvme: RTKit: syslog message: cmd.c:742: Oldest high water mark moved up to 26,tag 501, cmdQ CQ_IMMED
[144986.697914] nvme-apple 393cc0000.nvme: RTKit: syslog message: cmd.c:742: Oldest high water mark moved up to 27,tag 501, cmdQ CQ_IMMED
[144987.697902] nvme-apple 393cc0000.nvme: RTKit: syslog message: cmd.c:742: Oldest high water mark moved up to 28,tag 501, cmdQ CQ_IMMED
[144988.697912] nvme-apple 393cc0000.nvme: RTKit: syslog message: cmd.c:742: Oldest high water mark moved up to 29,tag 501, cmdQ CQ_IMMED
[144989.697914] nvme-apple 393cc0000.nvme: RTKit: syslog message: cmd.c:742: Oldest high water mark moved up to 30,tag 501, cmdQ CQ_IMMED
[144990.697926] nvme-apple 393cc0000.nvme: RTKit: syslog message: cmd.c:742: Oldest high water mark moved up to 31,tag 501, cmdQ CQ_IMMED
[144991.697935] nvme-apple 393cc0000.nvme: RTKit: syslog message: cmd.c:742: Oldest high water mark moved up to 32,tag 501, cmdQ CQ_IMMED
[144992.697948] nvme-apple 393cc0000.nvme: RTKit: syslog message: cmd.c:742: Oldest high water mark moved up to 33,tag 501, cmdQ CQ_IMMED
[144993.697953] nvme-apple 393cc0000.nvme: RTKit: syslog message: cmd.c:742: Oldest high water mark moved up to 34,tag 501, cmdQ CQ_IMMED
[144994.697974] nvme-apple 393cc0000.nvme: RTKit: syslog message: cmd.c:742: Oldest high water mark moved up to 35,tag 501, cmdQ CQ_IMMED
[144995.697974] nvme-apple 393cc0000.nvme: RTKit: syslog message: cmd.c:742: Oldest high water mark moved up to 36,tag 501, cmdQ CQ_IMMED
[144996.697974] nvme-apple 393cc0000.nvme: RTKit: syslog message: cmd.c:742: Oldest high water mark moved up to 37,tag 501, cmdQ CQ_IMMED
[144997.697899] nvme-apple 393cc0000.nvme: RTKit: syslog message: cmd.c:742: Oldest high water mark moved up to 38,tag 501, cmdQ CQ_IMMED
[145078.697928] nvme-apple 393cc0000.nvme: RTKit: syslog message: cmd.c:742: Oldest high water mark moved up to 119,tag 501, cmdQ CQ_IMMED
...
[145079.697914] nvme-apple 393cc0000.nvme: RTKit: syslog message: cmd.c:742: Oldest high water mark moved up to 120,tag 501, cmdQ CQ_IMMED
[145080.697927] nvme-apple 393cc0000.nvme: RTKit: syslog message: cmd.c:742: Oldest high water mark moved up to 121,tag 501, cmdQ CQ_IMMED
[145081.697945] nvme-apple 393cc0000.nvme: RTKit: syslog message: cmd.c:742: Oldest high water mark moved up to 122,tag 501, cmdQ CQ_IMMED
[145082.697964] nvme-apple 393cc0000.nvme: RTKit: syslog message: cmd.c:742: Oldest high water mark moved up to 123,tag 501, cmdQ CQ_IMMED
[145083.697966] nvme-apple 393cc0000.nvme: RTKit: syslog message: cmd.c:742: Oldest high water mark moved up to 124,tag 501, cmdQ CQ_IMMED
[145084.155363] nvme nvme0: Device not ready; aborting reset, CSTS=0x5
[145085.210528] nvme-apple 393cc0000.nvme: PM: dpm_run_callback(): 0xffff8000808abf60 returns -62
[145085.210537] nvme-apple 393cc0000.nvme: PM: failed to suspend: error -62
[145085.210569] PM: Some devices failed to suspend, or early wake event detected
[145085.715081] xhci-hcd xhci-hcd.3.auto: xHC error in resume, USBSTS 0x411, Reinit
[145085.715088] usb usb1: root hub lost power or was reset
[145085.715092] usb usb2: root hub lost power or was reset
[145085.791949] apple-dcp 289c00000.dcp: resume: HPD connected:0

and I could take pictures of basically the same dmesg on my M1 laptop.

In the case of shutdown, if I wait a bit (order one minute), then the laptop is able to shutdown. The relevant logs from the console:

- runit: leave stage: /etc/runit/3
- runit: sending KILL signal to all processes...
- runit: system reboot
[ 4272.725691] nvme: nvme0: Device not ready; aborting shutdown, CSTS=0x5
[ 4392.729666] nvme: nvme0: Device not ready; aborting reset, CSTS=0x5

I am on Void 6.17.8+1-asahi_1 aarch64, and OS firmware: 13.5.

Some possibly relevant messages in the logs:

nvme-apple 27bcc0000.nvme: RTKit: Initializing (protocol version 12)
nvme-apple 27bcc0000.nvme: RTKit: syslog message: cmd.c:6546:  boot mode normal
nvme-apple 27bcc0000.nvme: RTKit: syslog message: util.c:4609: element=PANICLOG written size=4096, host request trimmed to end of written content
nvme-apple 27bcc0000.nvme: RTKit: syslog message: util.c:4633: Util read unmap element: 8, lba: 1, size : 3
nvme-apple 27bcc0000.nvme: RTKit: syslog message: blog.c:102: New BlogBuf low 28
nvme-apple 27bcc0000.nvme: RTKit: syslog message: blog.c:102: New BlogBuf low 27