FreeNAS-9.3-STABLE-201501162230
AMD Athlon(tm) II X2 260 Processor
7908MB non-ecc
Asus M5A78L-M LX mainboard
Freenas alert emails were generated early morning saying that a drive had recorded a SMART error followed by an alert to say the volume had been degraded. When I went to check the Freenas webpage the next day the freenas box was completely offline, no ping response. When I checked the physical box it had rebooted but was trying to boot off of a hard drive instead of the USB (I'm pretty sure I had the boot config setup for USB but this system had been up for over a year now so maybe not). After resetting the boot to USB, Freenas started Ok.
My question is what has made Freenas reboot after the drive failure? I've pasted logs below
The errors started at 23:52 with the SMART errors logged at 00:42
Many errors logged until at 01:19 the drive is logged as being detached but drive errors continue to be logged until at 01:19:34 a swap_pager: I/O error appears followed by vm_fault.
These two last errors appear to be repeated for many megabytes of message logfile until the system reboots itself.
The drive failure and degradation appear to have completed gracefully, but what caused the swap_pager errors?
The pool is 3 x 2Tb vdev's, each vdev is a 2Tb mirrored pair.
AMD Athlon(tm) II X2 260 Processor
7908MB non-ecc
Asus M5A78L-M LX mainboard
Freenas alert emails were generated early morning saying that a drive had recorded a SMART error followed by an alert to say the volume had been degraded. When I went to check the Freenas webpage the next day the freenas box was completely offline, no ping response. When I checked the physical box it had rebooted but was trying to boot off of a hard drive instead of the USB (I'm pretty sure I had the boot config setup for USB but this system had been up for over a year now so maybe not). After resetting the boot to USB, Freenas started Ok.
My question is what has made Freenas reboot after the drive failure? I've pasted logs below
The errors started at 23:52 with the SMART errors logged at 00:42
Many errors logged until at 01:19 the drive is logged as being detached but drive errors continue to be logged until at 01:19:34 a swap_pager: I/O error appears followed by vm_fault.
These two last errors appear to be repeated for many megabytes of message logfile until the system reboots itself.
The drive failure and degradation appear to have completed gracefully, but what caused the swap_pager errors?
The pool is 3 x 2Tb vdev's, each vdev is a 2Tb mirrored pair.
Code:
[root@freenas] ~# zpool status pool: bigvol state: DEGRADED status: One or more devices could not be opened. Sufficient replicas exist for the pool to continue functioning in a degraded state. action: Attach the missing device and online it using 'zpool online'. see: http://illumos.org/msg/ZFS-8000-2Q scan: scrub repaired 0 in 22h5m with 0 errors on Wed Jun 29 23:06:03 2016 config: NAME STATE READ WRITE CKSUM bigvol DEGRADED 0 0 0 mirror-0 ONLINE 0 0 0 ada0p2 ONLINE 0 0 0 ada1p2 ONLINE 0 0 0 mirror-1 DEGRADED 0 0 0 ada2p2 ONLINE 0 0 0 5190664789547636286 UNAVAIL 0 0 0 was /dev/ada3p2 mirror-2 ONLINE 0 0 0 gptid/4292fe69-c9fe-11e0-a5db-f46d04cdc0ac ONLINE 0 0 0 gptid/43b1637b-c9fe-11e0-a5db-f46d04cdc0ac ONLINE 0 0 0 errors: No known data errors
Code:
Jul 12 23:52:40 freenas ahcich3: Timeout on slot 1 port 0 Jul 12 23:52:40 freenas ahcich3: is 00000000 cs 00000002 ss 00000000 rs 00000002 tfd c0 serr 00000800 cmd 0000e117 Jul 12 23:52:40 freenas (ada3:ahcich3:0:0:0): FLUSHCACHE48. ACB: ea 00 00 00 0040 00 00 00 00 00 00 Jul 12 23:52:40 freenas (ada3:ahcich3:0:0:0): CAM status: Command timeout Jul 12 23:52:40 freenas (ada3:ahcich3:0:0:0): Retrying command Jul 13 00:00:00 freenas syslog-ng[76777]: Configuration reload request received, reloading configuration; Jul 13 00:01:41 freenas ahcich3: Timeout on slot 21 port 0 Jul 13 00:01:41 freenas ahcich3: is 00000000 cs 00200000 ss 00000000 rs 00200000 tfd c0 serr 00000000 cmd 0000f517 Jul 13 00:01:41 freenas (ada3:ahcich3:0:0:0): FLUSHCACHE48. ACB: ea 00 00 00 0040 00 00 00 00 00 00 Jul 13 00:01:41 freenas (ada3:ahcich3:0:0:0): CAM status: Command timeout Jul 13 00:01:41 freenas (ada3:ahcich3:0:0:0): Retrying command Jul 13 00:18:17 freenas ahcich3: Timeout on slot 3 port 0 Jul 13 00:18:17 freenas ahcich3: is 00000000 cs 00000008 ss 00000000 rs 00000008 tfd c0 serr 00000000 cmd 0000e317 Jul 13 00:18:17 freenas (ada3:ahcich3:0:0:0): FLUSHCACHE48. ACB: ea 00 00 00 0040 00 00 00 00 00 00 Jul 13 00:18:17 freenas (ada3:ahcich3:0:0:0): CAM status: Command timeout Jul 13 00:18:17 freenas (ada3:ahcich3:0:0:0): Retrying command Jul 13 00:19:16 freenas ahcich3: Timeout on slot 30 port 0 Jul 13 00:19:16 freenas ahcich3: is 00000000 cs 00000000 ss c00001ff rs c00001ff tfd 40 serr 00000000 cmd 0000e817 Jul 13 00:19:16 freenas (ada3:ahcich3:0:0:0): READ_FPDMA_QUEUED. ACB: 60 0b ca d1 58 40 d6 00 00 00 00 00 Jul 13 00:19:16 freenas (ada3:ahcich3:0:0:0): CAM status: Command timeout Jul 13 00:19:16 freenas (ada3:ahcich3:0:0:0): Retrying command Jul 13 00:29:54 freenas ahcich3: Timeout on slot 21 port 0 Jul 13 00:29:54 freenas ahcich3: is 00000000 cs 00200000 ss 00000000 rs 00200000 tfd c0 serr 00000000 cmd 0000f517 Jul 13 00:29:54 freenas (ada3:ahcich3:0:0:0): FLUSHCACHE48. ACB: ea 00 00 00 0040 00 00 00 00 00 00 Jul 13 00:29:54 freenas (ada3:ahcich3:0:0:0): CAM status: Command timeout Jul 13 00:29:54 freenas (ada3:ahcich3:0:0:0): Retrying command Jul 13 00:30:28 freenas ahcich3: Timeout on slot 0 port 0 Jul 13 00:30:28 freenas ahcich3: is 00000000 cs 00000000 ss 000007ff rs 000007ff tfd 40 serr 00000000 cmd 0000ea17 Jul 13 00:30:28 freenas (ada3:ahcich3:0:0:0): READ_FPDMA_QUEUED. ACB: 60 0b 7c dc a6 40 e6 00 00 00 00 00 Jul 13 00:30:28 freenas (ada3:ahcich3:0:0:0): CAM status: Command timeout Jul 13 00:31:49 freenas ahcich3: Timeout on slot 3 port 0 Jul 13 00:31:49 freenas ahcich3: is 00000000 cs 00000000 ss 000000f8 rs 000000f8 tfd 40 serr 00000000 cmd 0000e717 Jul 13 00:31:49 freenas (ada3:ahcich3:0:0:0): WRITE_FPDMA_QUEUED. ACB: 61 08 c7ca ed 40 50 00 00 00 00 00 Jul 13 00:31:49 freenas (ada3:ahcich3:0:0:0): CAM status: Command timeout Jul 13 00:31:49 freenas (ada3:ahcich3:0:0:0): Retrying command Jul 13 00:38:47 freenas ahcich3: Timeout on slot 3 port 0 Jul 13 00:38:47 freenas ahcich3: is 00000000 cs 00000000 ss 00001ff8 rs 00001ff8 tfd 40 serr 00000000 cmd 0000ec17 Jul 13 00:38:47 freenas (ada3:ahcich3:0:0:0): WRITE_FPDMA_QUEUED. ACB: 61 00 cc0a 2b 40 51 00 00 01 00 00 Jul 13 00:38:47 freenas (ada3:ahcich3:0:0:0): CAM status: Command timeout Jul 13 00:38:47 freenas (ada3:ahcich3:0:0:0): Retrying command Jul 13 00:42:25 freenas smartd[89600]: Device: /dev/ada3, FAILED SMART self-check. BACK UP DATA NOW! Jul 13 00:42:50 freenas smartd[89600]: Device: /dev/ada3, 1 Currently unreadable (pending) sectors Jul 13 00:42:52 freenas smartd[89600]: Device: /dev/ada3, 1 Offline uncorrectable sectors Jul 13 00:42:53 freenas smartd[89600]: Device: /dev/ada3, Failed SMART usage Attribute: 5 Reallocated_Sector_Ct. Jul 13 00:48:45 freenas (ada3:ahcich3:0:0:0): READ_FPDMA_QUEUED. ACB: 60 00 8d fe 91 40 00 00 00 01 00 00 Jul 13 00:48:45 freenas (ada3:ahcich3:0:0:0): CAM status: ATA Status Error Jul 13 00:48:45 freenas (ada3:ahcich3:0:0:0): ATA status: 41 (DRDY ERR), error:40 (UNC ) Jul 13 00:48:45 freenas (ada3:ahcich3:0:0:0): RES: 41 40 dd fe 91 00 00 00 00 00 01 Jul 13 00:48:45 freenas (ada3:ahcich3:0:0:0): Retrying command Jul 13 00:48:54 freenas (ada3:ahcich3:0:0:0): READ_FPDMA_QUEUED. ACB: 60 00 8d fe 91 40 00 00 00 01 00 00 Jul 13 00:48:54 freenas (ada3:ahcich3:0:0:0): CAM status: ATA Status Error Jul 13 00:48:54 freenas (ada3:ahcich3:0:0:0): ATA status: 41 (DRDY ERR), error:40 (UNC ) Jul 13 00:48:54 freenas (ada3:ahcich3:0:0:0): RES: 41 40 e0 fe 91 00 00 00 00 00 01 Jul 13 00:48:54 freenas (ada3:ahcich3:0:0:0): Retrying command Jul 13 00:49:01 freenas (ada3:ahcich3:0:0:0): READ_FPDMA_QUEUED. ACB: 60 00 8d fe 91 40 00 00 00 01 00 00 Jul 13 00:49:01 freenas (ada3:ahcich3:0:0:0): CAM status: ATA Status Error Jul 13 00:49:01 freenas (ada3:ahcich3:0:0:0): ATA status: 41 (DRDY ERR), error:40 (UNC ) Jul 13 00:49:01 freenas (ada3:ahcich3:0:0:0): RES: 41 40 e0 fe 91 00 00 00 00 00 01 Jul 13 00:49:01 freenas (ada3:ahcich3:0:0:0): Retrying command Jul 13 00:49:09 freenas (ada3:ahcich3:0:0:0): READ_FPDMA_QUEUED. ACB: 60 00 8d fe 91 40 00 00 00 01 00 00 Jul 13 00:49:09 freenas (ada3:ahcich3:0:0:0): CAM status: ATA Status Error Jul 13 00:49:09 freenas (ada3:ahcich3:0:0:0): ATA status: 41 (DRDY ERR), error:40 (UNC ) Jul 13 00:49:09 freenas (ada3:ahcich3:0:0:0): RES: 41 40 e0 fe 91 00 00 00 00 00 01 Jul 13 00:49:09 freenas (ada3:ahcich3:0:0:0): Retrying command Jul 13 00:49:18 freenas (ada3:ahcich3:0:0:0): READ_FPDMA_QUEUED. ACB: 60 00 8d fe 91 40 00 00 00 01 00 00 Jul 13 00:49:18 freenas (ada3:ahcich3:0:0:0): CAM status: ATA Status Error Jul 13 00:49:18 freenas (ada3:ahcich3:0:0:0): ATA status: 41 (DRDY ERR), error:40 (UNC ) Jul 13 00:49:18 freenas (ada3:ahcich3:0:0:0): RES: 41 40 e0 fe 91 00 00 00 00 00 01 Jul 13 00:49:18 freenas (ada3:ahcich3:0:0:0): Error 5, Retries exhausted Jul 13 00:49:28 freenas (ada3:ahcich3:0:0:0): READ_FPDMA_QUEUED. ACB: 60 80 8d ff 91 40 00 00 00 00 00 00 Jul 13 00:49:28 freenas (ada3:ahcich3:0:0:0): CAM status: ATA Status Error ... Jul 13 01:19:34 freenas (aprobe0:ahcich3:0:0:0): Error 5, Retries exhausted Jul 13 01:19:34 freenas ada3 at ahcich3 bus 0 scbus3 target 0 lun 0 Jul 13 01:19:34 freenas ada3: <ST32000644NS SN12> s/n 9WM66121 detached Jul 13 01:19:34 freenas (ada3:ahcich3:0:0:0): SETFEATURES ENABLE RCACHE. ACB: ef aa 00 00 00 40 00 00 00 00 00 00 Jul 13 01:19:34 freenas (ada3:ahcich3:0:0:0): CAM status: ATA Status Error Jul 13 01:19:34 freenas (ada3:ahcich3:0:0:0): ATA status: 71 (DRDY DF SERV ERR), error: 04 (ABRT ) Jul 13 01:19:34 freenas (ada3:ahcich3:0:0:0): RES: 71 04 91 00 32 40 00 00 00 04 00 Jul 13 01:19:34 freenas (ada3:ahcich3:0:0:0): Error 5, Periph was invalidated Jul 13 01:19:34 freenas (ada3:ahcich3:0:0:0): WRITE_DMA48. ACB: 35 00 c6 84 07 40 ac 00 00 00 00 01 Jul 13 01:19:34 freenas (ada3:ahcich3:0:0:0): CAM status: Unconditionally Re-queue Request Jul 13 01:19:34 freenas (ada3:ahcich3:0:0:0): Error 5, Periph was invalidated Jul 13 01:19:34 freenas ahcich3: Error while READ LOG EXT Jul 13 01:19:34 freenas (ada3:ahcich3:0:0:0): WRITE_FPDMA_QUEUED. ACB: 61 00 c683 07 40 ac 00 00 01 00 00 Jul 13 01:19:34 freenas (ada3:ahcich3:0:0:0): CAM status: ATA Status Error Jul 13 01:19:34 freenas (ada3:ahcich3:0:0:0): ATA status: 00 () Jul 13 01:19:34 freenas (ada3:ahcich3:0:0:0): ATA status: 00 () Jul 13 01:19:34 freenas (ada3:ahcich3:0:0:0): RES: 00 00 00 00 00 00 00 00 00 00 00 Jul 13 01:19:34 freenas (ada3:ahcich3:0:0:0): Error 5, Periph was invalidated Jul 13 01:19:34 freenas ahcich3: Error while READ LOG EXT Jul 13 01:19:34 freenas (ada3:ahcich3:0:0:0): WRITE_FPDMA_QUEUED. ACB: 61 00 c686 07 40 ac 00 00 01 00 00 Jul 13 01:19:34 freenas (ada3:ahcich3:0:0:0): CAM status: ATA Status Error Jul 13 01:19:34 freenas (ada3:ahcich3:0:0:0): ATA status: 00 () Jul 13 01:19:34 freenas (ada3:ahcich3:0:0:0): RES: 00 00 00 00 00 00 00 00 00 00 00 Jul 13 01:19:34 freenas (ada3:ahcich3:0:0:0): Error 5, Periph was invalidated Jul 13 01:19:34 freenas (ada3:ahcich3:0:0:0): WRITE_FPDMA_QUEUED. ACB: 61 00 c687 07 40 ac 00 00 01 00 00 Jul 13 01:19:34 freenas (ada3:ahcich3:0:0:0): CAM status: ATA Status Error Jul 13 01:19:34 freenas (ada3:ahcich3:0:0:0): ATA status: 00 () Jul 13 01:19:34 freenas (ada3:ahcich3:0:0:0): RES: 00 00 00 00 00 00 00 00 00 00 00 Jul 13 01:19:34 freenas (ada3:ahcich3:0:0:0): Error 5, Periph was invalidated Jul 13 01:19:34 freenas (ada3:ahcich3:0:0:0): WRITE_FPDMA_QUEUED. ACB: 61 00 c688 07 40 ac 00 00 01 00 00 Jul 13 01:19:34 freenas (ada3:ahcich3:0:0:0): CAM status: ATA Status Error Jul 13 01:19:34 freenas (ada3:ahcich3:0:0:0): Error 5, Periph was invalidated Jul 13 01:19:34 freenas (0:4:0/0): WRITE(16). CDB: 8a 08 00 00 00 00 00 5f 18 f8 00 00 01 58 00 00 Jul 13 01:19:34 freenas (0:4:0/0): Tag: 0x7205423a, type 1 Jul 13 01:19:34 freenas (0:4:0/0): ctl_process_done: 148 seconds Jul 13 01:19:34 freenas swap_pager: I/O error - pagein failed; blkno 1584607,size 8192, error 6 Jul 13 01:19:34 freenas vm_fault: pager read error, pid 1338 (devd) Jul 13 01:19:35 freenas swap_pager: I/O error - pagein failed; blkno 1573901,size 4096, error 6 Jul 13 01:19:35 freenas vm_fault: pager read error, pid 1338 (devd) Jul 13 01:19:35 freenas kernel: Failed to write core file for process devd (error 14) Jul 13 01:19:35 freenas kernel: Failed to write core file for process devd (error 14) Jul 13 01:19:35 freenas kernel: pid 1338 (devd), uid 0: exited on signal 11 Jul 13 01:19:35 freenas swap_pager: I/O error - pagein failed; blkno 1582485,size 4096, error 6 Jul 13 01:19:35 freenas vm_fault: pager read error, pid 1 (init) Jul 13 01:19:36 freenas swap_pager: I/O error - pagein failed; blkno 1574041,size 8192, error 6 Jul 13 01:19:36 freenas vm_fault: pager read error, pid 1 (init) Jul 13 01:19:36 freenas swap_pager: I/O error - pagein failed; blkno 1574041,size 8192, error 6 ... Jul 13 01:21:56 freenas vm_fault: pager read error, pid 1 (init) Jul 13 01:21:56 freenas swap_pager: I/O error - pagein failed; blkno 1574041,size 8192, error 6