Re: kern/56479: Crash in ata_recovery_resume

[Andreas Gustafsson <gson%gson.org@localhost>]

The following reply was made to PR kern/56479; it has been noted by GNATS.

From: Andreas Gustafsson <gson%gson.org@localhost>
To: gnats-bugs%netbsd.org@localhost
Cc: 
Subject: Re: kern/56479: Crash in ata_recovery_resume
Date: Sun, 30 Jan 2022 12:36:36 +0200

 It happened again last night.  The machine logged 63 "device timeout
 writing fsbn" errors to the console and then paniced.  Here's the end
 of the console output:
 
 [ 2760684.070946] wd3d: device timeout writing fsbn 7013874752 of 7013874752-7013874879 (wd3 bn 7013874752; cn 6958209 tn 1 sn 17), xfer 818, retry 1
 [ 2760684.229029] wd3d: device timeout writing fsbn 7013874624 of 7013874624-7013874751 (wd3 bn 7013874624; cn 6958208 tn 15 sn 15), xfer 780, retry 1
 [ 2760684.388150] wd3d: device timeout writing fsbn 7013874368 of 7013874368-7013874431 (wd3 bn 7013874368; cn 6958208 tn 11 sn 11), xfer 6e8, retry 1
 [ 2760684.547271] wd3d: device timeout writing fsbn 7013874240 of 7013874240-7013874367 (wd3 bn 7013874240; cn 6958208 tn 9 sn 9), xfer f8, retry 1
 [ 2760684.703272] wd3d: device timeout writing fsbn 7013873984 of 7013873984-7013874047 (wd3 bn 7013873984; cn 6958208 tn 5 sn 5), xfer 650, retry 1
 [ 2760684.860314] wd3d: device timeout writing fsbn 7013873856 of 7013873856-7013873983 (wd3 bn 7013873856; cn 6958208 tn 3 sn 3), xfer 5b8, retry 1
 [ 2760685.017356] wd3d: device timeout writing fsbn 7013873472 of 7013873472-7013873535 (wd3 bn 7013873472; cn 6958207 tn 12 sn 60), xfer 520, retry 1
 [ 2760685.176477] wd3d: device timeout writing fsbn 7013873344 of 7013873344-7013873471 (wd3 bn 7013873344; cn 6958207 tn 10 sn 58), xfer 60, retry 1
 [ 2760685.334559] wd3d: device timeout writing fsbn 7013873216 of 7013873216-7013873343 (wd3 bn 7013873216; cn 6958207 tn 8 sn 56), xfer 488, retry 1
 [ 2760685.492640] wd3d: device timeout writing fsbn 7013873088 of 7013873088-7013873151 (wd3 bn 7013873088; cn 6958207 tn 6 sn 54), xfer 3f0, retry 1
 [ 2760685.650722] wd3d: device timeout writing fsbn 7013872832 of 7013872832-7013872895 (wd3 bn 7013872832; cn 6958207 tn 2 sn 50), xfer 358, retry 1
 [ 2760685.808804] wd3d: device timeout writing fsbn 7013872704 of 7013872704-7013872831 (wd3 bn 7013872704; cn 6958207 tn 0 sn 48), xfer 2c0, retry 1
 [ 2760685.966886] wd3d: device timeout writing fsbn 7013872576 of 7013872576-7013872639 (wd3 bn 7013872576; cn 6958206 tn 14 sn 46), xfer 228, retry 1
 [ 2760686.126008] wd3d: device timeout writing fsbn 7013872192 of 7013872192-7013872255 (wd3 bn 7013872192; cn 6958206 tn 8 sn 40), xfer 190, retry 1
 [ 2760686.284088] wd3d: device timeout writing fsbn 7013872064 of 7013872064-7013872127 (wd3 bn 7013872064; cn 6958206 tn 6 sn 38), xfer 350, retry 1
 [ 2760686.442170] wd3d: device timeout writing fsbn 7013871936 of 7013871936-7013872063 (wd3 bn 7013871936; cn 6958206 tn 4 sn 36), xfer 2b8, retry 1
 [ 2760686.600252] wd3d: device timeout writing fsbn 7013871808 of 7013871808-7013871871 (wd3 bn 7013871808; cn 6958206 tn 2 sn 34), xfer 220, retry 1
 [ 2760686.758333] wd3d: device timeout writing fsbn 7013871680 of 7013871680-7013871807 (wd3 bn 7013871680; cn 6958206 tn 0 sn 32), xfer 188, retry 1
 [ 2760686.916416] wd3d: device timeout writing fsbn 7013871552 of 7013871552-7013871615 (wd3 bn 7013871552; cn 6958205 tn 14 sn 30), xfer f0, retry 1
 [ 2760687.074496] wd3d: device timeout writing fsbn 7013871424 of 7013871424-7013871551 (wd3 bn 7013871424; cn 6958205 tn 12 sn 28), xfer 58, retry 1
 [ 2760687.232577] wd3d: device timeout writing fsbn 7013871296 of 7013871296ry 1
 [ 2770780.456401] uvm_fault(0xffffffff81585c20, 0x0, 1) -> e
 [ 2770780.517013] fatal page fault in supervisor mode
 [ 2770780.577041] trap type 6 code 0 rip 0xffffffff8027bd27 cs 0x8 rflags 0x10286 cr2 0x10 ilevel 0 rsp 0xffff8e849432cf00
 [ 2770780.707101] curlwp 0xffff848a0f738900 pid 0.310 lowest kstack 0xffff8e849432a2c0
 [ 2770780.797143] panic: trap
 [ 2770780.827157] cpu19: Begin traceback...
 [ 2770780.877183] vpanic() at netbsd:vpanic+0x160
 [ 2770780.937208] snprintf() at netbsd:snprintf
 [ 2770780.987231] startlwp() at netbsd:startlwp
 [ 2770781.037257] alltraps() at netbsd:alltraps+0xbb
 [ 2770781.097281] ata_thread_run() at netbsd:ata_thread_run+0x249
 [ 2770781.167313] atabus_thread() at netbsd:atabus_thread+0x208
 [ 2770781.237347] cpu19: End traceback...
 
 [ 2770781.287371] dumping to dev 0,1 (offset=8, size=16753263):
 [ 2770781.347398] dump
 
 Batcktrace according to gdb:
 
 (gdb) bt
 #0  0xffffffff80222aaa in cpu_reboot ()
 #1  0xffffffff80994a96 in vpanic ()
 #2  0xffffffff80994b47 in panic ()
 #3  0xffffffff80224aed in trap ()
 #4  0xffffffff8021d56b in alltraps ()
 #5  0xffffffff8027bd27 in ata_recovery_resume ()
 #6  0xffffffff80279912 in ata_thread_run ()
 #7  0xffffffff8027a236 in atabus_thread ()
 #8  0xffffffff80209747 in lwp_trampoline ()
 #9  0x0000000000000000 in ?? ()
 
 The SMART error log of the disk in case is empty.  It uses SMR, so I
 would not be surprised if it's sometimes slow to respond.  Here's the
 dmesg output for the controller and disk:
 
 [     1.092336] ahcisata1 at pci0 dev 31 function 2: vendor 8086 product 8d02 (rev. 0x05)
 [     1.092336] ahcisata1: 64-bit DMA
 [     1.092336] ahcisata1: AHCI revision 1.30, 6 ports, 32 slots, CAP 0xcb30ff45<EMS,PSC,SSC,PMD,ISS=0x3=Gen3,SCLO,SAL,SSS,SNCQ,S64A>
 [     1.092336] ahcisata1: interrupting at msi5 vec 0
 [     1.092336] atabus4 at ahcisata1 channel 0
 [     1.092336] atabus5 at ahcisata1 channel 1
 [     1.092336] atabus6 at ahcisata1 channel 2
 [     1.092336] atabus7 at ahcisata1 channel 3
 [     1.092336] atabus8 at ahcisata1 channel 4
 [     1.092336] atabus9 at ahcisata1 channel 5
 [     3.251001] ahcisata1 port 1: device present, speed: 6.0Gb/s
 [     6.532170] wd3(ahcisata1:1:0): using PIO mode 4, DMA mode 2, Ultra-DMA mode 6 (Ultra/133) (using DMA), NCQ (31 tags)
 [...]
 [     5.921953] wd3: <ST5000LM000-2AN170>
 [     5.961967] wd3: drive supports 1-sector PIO transfers, LBA48 addressing
 [     5.961967] wd3: 4657 GB, 9690021 cyl, 16 head, 63 sec, 512 bytes/sect x 9767541168 sectors (0 bytes/physsect; first aligned sector: 8)
 [     6.422131] wd3: GPT GUID: 31a830f6-dace-4062-ab89-f6911c261385
 [     6.422131] dk2 at wd3: "65183669-9719-47da-9e2a-09a1f9a7bf6d", 9767538688 blocks at 2048, type: ffs
 [     6.532170] wd3: drive supports PIO mode 4, DMA mode 2, Ultra-DMA mode 6 (Ultra/133), WRITE DMA FUA, NCQ (32 tags)
 [     6.532170] wd3(ahcisata1:1:0): using PIO mode 4, DMA mode 2, Ultra-DMA mode 6 (Ultra/133) (using DMA), NCQ (31 tags)
 
 -- 
 Andreas Gustafsson, gson%gson.org@localhost