Understanding scrubing + Boot pool unrecoverable error after srub

haagen

Cadet
Joined
Apr 5, 2019
Messages
8
Hi guys,

I don't seem to understand the scrubbing process.
I have scheduled my scrubs to be:

Threshold: 28 days
Minute: 0
Hour: 9
Day of month: 3
Month: *
Day of Week: *
Enabled: Yes

Now what I do not understand is, why it ran today -> 9.9.2019

Would you be so kind and clear this one for me?

And my second issue is the state of the boot pool after scrubbing process. I'm running FreeNAS on cheap SSD instead of Flash drive.
This is the email I got:
Code:
New alerts:
* Boot Pool Status Is ONLINE: One or more devices has experienced an unrecoverable error. An attempt was made to correct the error. Applications are unaffected.

Current alerts:
* Boot Pool Status Is ONLINE: One or more devices has experienced an unrecoverable error. An attempt was made to correct the error. Applications are unaffected.
[\CODE]

Here is SMART data:
Code:
smartctl -a  /dev/ada6
smartctl 6.6 2017-11-05 r4594 [FreeBSD 11.2-STABLE amd64] (local build)
Copyright (C) 2002-17, Bruce Allen, Christian Franke, www.smartmontools.org

=== START OF INFORMATION SECTION ===
Device Model:     Patriot Burst
Serial Number:    ***********
Firmware Version: SBFM61.3
User Capacity:    120,034,123,776 bytes [120 GB]
Sector Size:      512 bytes logical/physical
Rotation Rate:    Solid State Device
Form Factor:      2.5 inches
Device is:        Not in smartctl database [for details use: -P showall]
ATA Version is:   ACS-4 (minor revision not indicated)
SATA Version is:  SATA 3.2, 6.0 Gb/s (current: 6.0 Gb/s)
Local Time is:    Mon Sep  9 21:33:41 2019 CEST
SMART support is: Available - device has SMART capability.
SMART support is: Enabled

=== START OF READ SMART DATA SECTION ===
SMART overall-health self-assessment test result: PASSED

General SMART Values:
Offline data collection status:  (0x00) Offline data collection activity
                                        was never started.
                                        Auto Offline Data Collection: Disabled.
Self-test execution status:      (   0) The previous self-test routine completed
                                        without error or no self-test has ever
                                        been run.
Total time to complete Offline
data collection:                (65535) seconds.
Offline data collection
capabilities:                    (0x79) SMART execute Offline immediate.
                                        No Auto Offline data collection support.
                                        Suspend Offline collection upon new
                                        command.
                                        Offline surface scan supported.
                                        Self-test supported.
                                        Conveyance Self-test supported.
                                        Selective Self-test supported.
SMART capabilities:            (0x0003) Saves SMART data before entering
                                        power-saving mode.
                                        Supports SMART auto save timer.
Error logging capability:        (0x01) Error logging supported.
                                        General Purpose Logging supported.
Short self-test routine
recommended polling time:        (   2) minutes.
Extended self-test routine
recommended polling time:        (  30) minutes.
Conveyance self-test routine
recommended polling time:        (   6) minutes.

SMART Attributes Data Structure revision number: 16
Vendor Specific SMART Attributes with Thresholds:
ID# ATTRIBUTE_NAME          FLAG     VALUE WORST THRESH TYPE      UPDATED  WHEN_FAILED RAW_VALUE
  1 Raw_Read_Error_Rate     0x000b   100   100   050    Pre-fail  Always       -       0
  9 Power_On_Hours          0x0012   100   100   000    Old_age   Always       -       277
12 Power_Cycle_Count       0x0012   100   100   000    Old_age   Always       -       13
168 Unknown_Attribute       0x0012   100   100   000    Old_age   Always       -       0
170 Unknown_Attribute       0x0003   100   100   010    Pre-fail  Always       -       52
173 Unknown_Attribute       0x0012   100   100   000    Old_age   Always       -       1
192 Power-Off_Retract_Count 0x0012   100   100   000    Old_age   Always       -       7
194 Temperature_Celsius     0x0023   067   067   000    Pre-fail  Always       -       33 (Min/Max 33/33)
218 Unknown_Attribute       0x000b   100   100   050    Pre-fail  Always       -       0
231 Temperature_Celsius     0x0013   100   100   000    Pre-fail  Always       -       100
241 Total_LBAs_Written      0x0012   100   100   000    Old_age   Always       -       3

SMART Error Log Version: 1
No Errors Logged

SMART Self-test log structure revision number 1
Num  Test_Description    Status                  Remaining  LifeTime(hours)  LBA_of_first_error
# 1  Short offline       Completed without error       00%       277         -
# 2  Short offline       Completed without error       00%       253         -
# 3  Short offline       Completed without error       00%       229         -

SMART Selective self-test log data structure revision number 0
Note: revision number not 1 implies that no selective self-test has ever been run
SPAN  MIN_LBA  MAX_LBA  CURRENT_TEST_STATUS
    1        0        0  Not_testing
    2        0        0  Not_testing
    3        0        0  Not_testing
    4        0        0  Not_testing
    5        0        0  Not_testing
Selective self-test flags (0x0):
  After scanning selected spans, do NOT read-scan remainder of disk.
If Selective self-test is pending on power-up, resume after 0 minute delay.
Here goes my boot zpool status:
Code:
root@freenas[/var/log]# zpool status -v
  pool: freenas-boot
 state: ONLINE
  scan: scrub repaired 0 in 0 days 17:28:19 with 0 errors on Mon Sep  9 21:13:19 2019
config:

        NAME        STATE     READ WRITE CKSUM
        freenas-boot  ONLINE       0     0     0
          ada6p2    ONLINE       0     0     0

errors: No known data errors
Server became unrsponsive, I was not able to log in - unfortunately didn't take screenshots in KVM and r I am able to find the errors in logs. But I could't do anything without the reboot. Is there any way to track down this issue? Is it just that the SSD is too "slow"... ? Thank you!
 

haagen

Cadet
Joined
Apr 5, 2019
Messages
8
Here is the error I saw in KVM extracted from /var/log/messages:

Code:
Sep  9 03:45:00 freenas ZFS: vdev state changed, pool_guid=5950947911649441828 vdev_guid=4378202468877604629
Sep  9 03:45:33 freenas ahcich7: Timeout on slot 4 port 0
Sep  9 03:45:33 freenas ahcich7: is 00000000 cs 00000000 ss 00007ff0 rs 00007ff0 tfd 40 serr 00000000 cmd 0004ce17
Sep  9 03:45:33 freenas (ada6:ahcich7:0:0:0): WRITE_FPDMA_QUEUED. ACB: 61 02 e8 ab 60 40 02 00 00 00 00 00
Sep  9 03:45:33 freenas (ada6:ahcich7:0:0:0): CAM status: Command timeout
Sep  9 03:45:33 freenas (ada6:ahcich7:0:0:0): Retrying command
Sep  9 03:46:06 freenas ahcich7: AHCI reset: device not ready after 31000ms (tfd = 00000080)
Sep  9 03:46:36 freenas ahcich7: Timeout on slot 15 port 0
Sep  9 03:46:36 freenas ahcich7: is 00000000 cs 00008000 ss 00000000 rs 00008000 tfd 80 serr 00000000 cmd 0004cf17
Sep  9 03:46:36 freenas (aprobe0:ahcich7:0:0:0): ATA_IDENTIFY. ACB: ec 00 00 00 00 40 00 00 00 00 00 00
Sep  9 03:46:36 freenas (aprobe0:ahcich7:0:0:0): CAM status: Command timeout
Sep  9 03:46:36 freenas (aprobe0:ahcich7:0:0:0): Retrying command
Sep  9 03:47:10 freenas ahcich7: AHCI reset: device not ready after 31000ms (tfd = 00000080)
Sep  9 03:47:39 freenas ahcich7: Timeout on slot 16 port 0
Sep  9 03:47:39 freenas ahcich7: is 00000000 cs 00010000 ss 00000000 rs 00010000 tfd 80 serr 00000000 cmd 0004d017
Sep  9 03:47:39 freenas (aprobe0:ahcich7:0:0:0): ATA_IDENTIFY. ACB: ec 00 00 00 00 40 00 00 00 00 00 00
Sep  9 03:47:39 freenas (aprobe0:ahcich7:0:0:0): CAM status: Command timeout
Sep  9 03:47:39 freenas (aprobe0:ahcich7:0:0:0): Error 5, Retries exhausted
Sep  9 03:48:13 freenas ahcich7: AHCI reset: device not ready after 31000ms (tfd = 00000080)
Sep  9 03:48:42 freenas ahcich7: Timeout on slot 17 port 0
Sep  9 03:48:42 freenas ahcich7: is 00000000 cs 00020000 ss 00000000 rs 00020000 tfd 80 serr 00000000 cmd 0004d117
Sep  9 03:48:42 freenas (aprobe0:ahcich7:0:0:0): ATA_IDENTIFY. ACB: ec 00 00 00 00 40 00 00 00 00 00 00
Sep  9 03:48:42 freenas (aprobe0:ahcich7:0:0:0): CAM status: Command timeout
Sep  9 03:48:42 freenas (aprobe0:ahcich7:0:0:0): Error 5, Retry was blocked
Sep  9 03:48:42 freenas ada6 at ahcich7 bus 0 scbus7 target 0 lun 0
Sep  9 03:48:42 freenas ada6: <Patriot Burst SBFM61.3> s/n D9AE07951C4800200724 detached
Sep  9 03:49:02 freenas xptioctl: pass driver is not in the kernel
Sep  9 03:49:02 freenas xptioctl: put "device pass" in your kernel config file
Sep  9 03:49:16 freenas ahcich7: AHCI reset: device not ready after 31000ms (tfd = 00000080)
Sep  9 03:49:46 freenas ahcich7: Timeout on slot 18 port 0
Sep  9 03:49:46 freenas ahcich7: is 00000000 cs 00040000 ss 00000000 rs 00040000 tfd 80 serr 00000000 cmd 0004d217
Sep  9 03:49:46 freenas (aprobe0:ahcich7:0:0:0): ATA_IDENTIFY. ACB: ec 00 00 00 00 40 00 00 00 00 00 00
Sep  9 03:49:46 freenas (aprobe0:ahcich7:0:0:0): CAM status: Command timeout
Sep  9 03:49:46 freenas (aprobe0:ahcich7:0:0:0): Retrying command
Sep  9 03:50:19 freenas ahcich7: AHCI reset: device not ready after 31000ms (tfd = 00000080)
Sep  9 03:50:49 freenas ahcich7: Timeout on slot 19 port 0
Sep  9 03:50:49 freenas ahcich7: is 00000000 cs 00080000 ss 00000000 rs 00080000 tfd 80 serr 00000000 cmd 0004d317
Sep  9 03:50:49 freenas (aprobe0:ahcich7:0:0:0): ATA_IDENTIFY. ACB: ec 00 00 00 00 40 00 00 00 00 00 00
Sep  9 03:50:49 freenas (aprobe0:ahcich7:0:0:0): CAM status: Command timeout
Sep  9 03:50:49 freenas (aprobe0:ahcich7:0:0:0): Error 5, Retries exhausted
Sep  9 03:51:40 freenas ahcich7: AHCI reset: device not ready after 31000ms (tfd = 00000080)
Sep  9 03:51:40 freenas ahcich7: Poll timeout on slot 20 port 0
Sep  9 03:51:40 freenas ahcich7: is 00000000 cs 00100000 ss 00000000 rs 00100000 tfd 80 serr 00000000 cmd 0004d417
Sep  9 03:51:40 freenas (aprobe0:ahcich7:0:0:0): SOFT_RESET. ACB: 00 00 00 00 00 00 00 00 00 00 00 00
Sep  9 03:51:40 freenas (aprobe0:ahcich7:0:0:0): CAM status: Command timeout
Sep  9 03:51:40 freenas (aprobe0:ahcich7:0:0:0): Error 5, Retries exhausted
Sep  9 03:52:10 freenas ahcich7: Timeout on slot 21 port 0
Sep  9 03:52:10 freenas ahcich7: is 00000000 cs 00200000 ss 00000000 rs 00200000 tfd 80 serr 00000000 cmd 0004d517
Sep  9 03:52:10 freenas (ada6:ahcich7:0:0:0): SETFEATURES ENABLE RCACHE. ACB: ef aa 00 00 00 40 00 00 00 00 00 00
Sep  9 03:52:10 freenas (ada6:ahcich7:0:0:0): CAM status: Command timeout
Sep  9 03:52:10 freenas (ada6:ahcich7:0:0:0): Error 5, Periph was invalidated
Sep  9 03:53:01 freenas ahcich7: AHCI reset: device not ready after 31000ms (tfd = 00000080)
Sep  9 03:53:01 freenas ahcich7: Poll timeout on slot 22 port 0
Sep  9 03:53:01 freenas ahcich7: is 00000000 cs 00400000 ss 00000000 rs 00400000 tfd 80 serr 00000000 cmd 0004d617
Sep  9 03:53:01 freenas (aprobe0:ahcich7:0:0:0): SOFT_RESET. ACB: 00 00 00 00 00 00 00 00 00 00 00 00
Sep  9 03:53:01 freenas (aprobe0:ahcich7:0:0:0): CAM status: Command timeout
Sep  9 03:53:01 freenas (aprobe0:ahcich7:0:0:0): Error 5, Retries exhausted
Sep  9 03:53:31 freenas ahcich7: Timeout on slot 23 port 0
Sep  9 03:53:31 freenas ahcich7: is 00000000 cs 00800000 ss 00000000 rs 00800000 tfd 80 serr 00000000 cmd 0004d717
Sep  9 03:53:31 freenas (ada6:ahcich7:0:0:0): SETFEATURES ENABLE WCACHE. ACB: ef 02 00 00 00 40 00 00 00 00 00 00
Sep  9 03:53:31 freenas (ada6:ahcich7:0:0:0): CAM status: Command timeout
Sep  9 03:53:31 freenas (ada6:ahcich7:0:0:0): Error 5, Periph was invalidated
Sep  9 03:54:01 freenas xptioctl: pass driver is not in the kernel
Sep  9 03:54:01 freenas xptioctl: put "device pass" in your kernel config file
Sep  9 03:54:01 freenas xptioctl: pass driver is not in the kernel
Sep  9 03:54:01 freenas xptioctl: put "device pass" in your kernel config file
Sep  9 03:54:02 freenas xptioctl: pass driver is not in the kernel
Sep  9 03:54:02 freenas xptioctl: put "device pass" in your kernel config file
Sep  9 03:54:22 freenas ahcich7: AHCI reset: device not ready after 31000ms (tfd = 00000080)
Sep  9 03:54:22 freenas ahcich7: Poll timeout on slot 24 port 0
Sep  9 03:54:22 freenas ahcich7: is 00000000 cs 01000000 ss 00000000 rs 01000000 tfd 80 serr 00000000 cmd 0004d817
Sep  9 03:54:22 freenas (aprobe0:ahcich7:0:0:0): SOFT_RESET. ACB: 00 00 00 00 00 00 00 00 00 00 00 00
Sep  9 03:54:22 freenas (aprobe0:ahcich7:0:0:0): CAM status: Command timeout
Sep  9 03:54:22 freenas (aprobe0:ahcich7:0:0:0): Error 5, Retries exhausted
Sep  9 03:54:52 freenas ahcich7: Timeout on slot 25 port 0
Sep  9 03:54:52 freenas ahcich7: is 00000000 cs fe00000f ss fe00000f rs fe00000f tfd 80 serr 00000000 cmd 0004d917
Sep  9 03:54:52 freenas (ada6:ahcich7:0:0:0): DSM TRIM. ACB: 06 01 00 00 00 40 00 00 00 00 01 00
Sep  9 03:54:52 freenas (ada6:ahcich7:0:0:0): CAM status: Unconditionally Re-queue Request
Sep  9 03:54:52 freenas (ada6:ahcich7:0:0:0): Error 5, Periph was invalidated
Sep  9 03:54:52 freenas (ada6:ahcich7:0:0:0): WRITE_FPDMA_QUEUED. ACB: 61 02 e8 ab 60 40 02 00 00 00 00 00
Sep  9 03:54:52 freenas (ada6:ahcich7:0:0:0): CAM status: Command timeout
Sep  9 03:54:52 freenas (ada6:ahcich7:0:0:0): Error 5, Periph was invalidated
Sep  9 03:54:52 freenas (ada6:ahcich7:0:0:0): WRITE_FPDMA_QUEUED. ACB: 61 04 67 38 40 40 01 00 00 00 00 00
Sep  9 03:54:52 freenas (ada6:ahcich7:0:0:0): CAM status: Unconditionally Re-queue Request
Sep  9 03:54:52 freenas (ada6:ahcich7:0:0:0): Error 5, Periph was invalidated
Sep  9 03:54:52 freenas (ada6:ahcich7:0:0:0): WRITE_FPDMA_QUEUED. ACB: 61 01 ea ab 60 40 02 00 00 00 00 00
Sep  9 03:54:52 freenas (ada6:ahcich7:0:0:0): CAM status: Unconditionally Re-queue Request
Sep  9 03:54:52 freenas (ada6:ahcich7:0:0:0): Error 5, Periph was invalidated
Sep  9 03:54:52 freenas (ada6:ahcich7:0:0:0): WRITE_FPDMA_QUEUED. ACB: 61 08 a7 51 60 40 02 00 00 00 00 00
Sep  9 03:54:52 freenas (ada6:ahcich7:0:0:0): CAM status: Unconditionally Re-queue Request
Sep  9 03:54:52 freenas (ada6:ahcich7:0:0:0): Error 5, Periph was invalidated
Sep  9 03:54:52 freenas (ada6:ahcich7:0:0:0): WRITE_FPDMA_QUEUED. ACB: 61 05 72 47 c0 40 07 00 00 00 00 00
Sep  9 03:54:52 freenas (ada6:ahcich7:0:0:0): CAM status: Unconditionally Re-queue Request
Sep  9 03:54:52 freenas (ada6:ahcich7:0:0:0): Error 5, Periph was invalidated
Sep  9 03:54:52 freenas (ada6:ahcich7:0:0:0): WRITE_FPDMA_QUEUED. ACB: 61 01 68 47 c0 40 07 00 00 00 00 00
Sep  9 03:54:52 freenas (ada6:ahcich7:0:0:0): CAM status: Unconditionally Re-queue Request
Sep  9 03:54:52 freenas (ada6:ahcich7:0:0:0): Error 5, Periph was invalidated
Sep  9 03:54:52 freenas (ada6:ahcich7:0:0:0): WRITE_FPDMA_QUEUED. ACB: 61 02 09 4b 00 40 05 00 00 00 00 00
Sep  9 03:54:52 freenas (ada6:ahcich7:0:0:0): CAM status: Unconditionally Re-queue Request
Sep  9 03:54:52 freenas (ada6:ahcich7:0:0:0): Error 5, Periph was invalidated
Sep  9 03:54:52 freenas (ada6:ahcich7:0:0:0): WRITE_FPDMA_QUEUED. ACB: 61 03 aa 37 e0 40 01 00 00 00 00 00
Sep  9 03:54:52 freenas (ada6:ahcich7:0:0:0): CAM status: Unconditionally Re-queue Request
Sep  9 03:54:52 freenas (ada6:ahcich7:0:0:0): Error 5, Periph was invalidated
Sep  9 03:54:52 freenas (ada6:ahcich7:0:0:0): WRITE_FPDMA_QUEUED. ACB: 61 02 69 47 c0 40 07 00 00 00 00 00
Sep  9 03:54:52 freenas (ada6:ahcich7:0:0:0): CAM status: Unconditionally Re-queue Request
Sep  9 03:54:52 freenas (ada6:ahcich7:0:0:0): Error 5, Periph was invalidated
Sep  9 03:54:52 freenas (ada6:ahcich7:0:0:0): WRITE_FPDMA_QUEUED. ACB: 61 04 6b 47 c0 40 07 00 00 00 00 00
Sep  9 03:54:52 freenas (ada6:ahcich7:0:0:0): CAM status: Unconditionally Re-queue Request
Sep  9 03:54:52 freenas (ada6:ahcich7:0:0:0): Error 5, Periph was invalidated
Sep  9 03:54:52 freenas (ada6:ahcich7:0:0:0): WRITE_FPDMA_QUEUED. ACB: 61 03 6f 47 c0 40 07 00 00 00 00 00
Sep  9 03:54:52 freenas (ada6:ahcich7:0:0:0): CAM status: Unconditionally Re-queue Request
Sep  9 03:54:52 freenas (ada6:ahcich7:0:0:0): Error 5, Periph was invalidated
Sep  9 03:54:52 freenas ZFS: vdev state changed, pool_guid=5950947911649441828 vdev_guid=4378202468877604629
Sep  9 03:54:52 freenas (ada6:ahcich7:0:0:0): Periph destroyed
Sep  9 03:55:43 freenas ahcich7: AHCI reset: device not ready after 31000ms (tfd = 00000080)
Sep  9 03:55:43 freenas ahcich7: Poll timeout on slot 4 port 0
Sep  9 03:55:43 freenas ahcich7: is 00000000 cs 00000010 ss 00000000 rs 00000010 tfd 80 serr 00000000 cmd 0004c417
Sep  9 03:55:43 freenas (aprobe0:ahcich7:0:0:0): SOFT_RESET. ACB: 00 00 00 00 00 00 00 00 00 00 00 00
Sep  9 03:55:43 freenas (aprobe0:ahcich7:0:0:0): CAM status: Command timeout
Sep  9 03:55:43 freenas (aprobe0:ahcich7:0:0:0): Error 5, Retries exhausted
 

haagen

Cadet
Joined
Apr 5, 2019
Messages
8
Actually I did not, I wasn't able to narrow down why this happened, but all scrubs after that were completely OK so far. When it happened, there was no other disk intensive operation.

Code:
  pool: freenas-boot

state: ONLINE

  scan: scrub repaired 0 in 0 days 00:00:04 with 0 errors on Wed Sep 18 03:45:04 2019

config:



        NAME        STATE     READ WRITE CKSUM

        freenas-boot  ONLINE       0     0     0

          ada6p2    ONLINE       0     0     0



errors: No known data errors


I will check the link you've provided. Thank you!
 
Top