I have had errors showing up shortly after I upgraded from FreeNAS 11.3-U5 to TrueNAS-12.0-U5. (I plan on upgrading to TrueNAS-12.0-U6 next weekend assuming that the release goes of smoothly.) I don't know if there is a connection or if it is just coincidence.
I tried searching, but I couldn't find a readable explanation of what causes/what is happening when an IDNF error is reported. (Is this a non-existent LBA or is it something else?)
I got message about an unrecoverable error on my main pool, so I had a look at the smart parameters, and it appears that the issue had to do with the error message:
I had a recurrence of the pool error condition, and that was easily cleared, and the passed a scrub without incident.
Any insight as as to if this Is this a TrueNAS error (ZFS issue), a hardware issue (Drive DA3, the HBA, a Memory Fault-NonECC) or just corruption (System experienced a bad shutdown due to UPS failure)?
I have included a grep of the relevent messages from /var/log/messages as well as the output from smartctl below. Any insight/assistance would be much appreciated. Thanks in advance.
Log Entries Related to First incident
Log Entries Related to Second incident
Latest Smart Output:
I tried searching, but I couldn't find a readable explanation of what causes/what is happening when an IDNF error is reported. (Is this a non-existent LBA or is it something else?)
I got message about an unrecoverable error on my main pool, so I had a look at the smart parameters, and it appears that the issue had to do with the error message:
Error: IDNF at LBA = ...
. The first time it happened, I was able to clear the error and I had about 100kb resilvered. I ran a badblocks (read only) on the disk as well as a full smart surface test and a zpool scrub--other than the IDNF errors there is no other indication of a problem. I had a recurrence of the pool error condition, and that was easily cleared, and the passed a scrub without incident.
Any insight as as to if this Is this a TrueNAS error (ZFS issue), a hardware issue (Drive DA3, the HBA, a Memory Fault-NonECC) or just corruption (System experienced a bad shutdown due to UPS failure)?
I have included a grep of the relevent messages from /var/log/messages as well as the output from smartctl below. Any insight/assistance would be much appreciated. Thanks in advance.
Log Entries Related to First incident
Code:
Sep 24 05:31:36 freenas (da3:mps0:0:5:0): CAM status: SCSI Status Error Sep 24 05:31:36 freenas (da3:mps0:0:5:0): SCSI status: Check Condition Sep 24 05:31:36 freenas (da3:mps0:0:5:0): SCSI sense: ILLEGAL REQUEST asc:21,0 (Logical block address out of range) Sep 24 05:31:36 freenas (da3:mps0:0:5:0): Info: 0x214e59dc0 Sep 24 05:31:36 freenas (da3:mps0:0:5:0): Error 22, Unretryable error
Log Entries Related to Second incident
Code:
Oct 2 14:02:00 freenas mps0: Controller reported scsi ioc terminated tgt 5 SMID 1646 loginfo 31080000 Oct 2 14:02:00 freenas mps0: (da3:mps0:0:5:0): WRITE(10). CDB: 2a 00 4f 20 6a b0 00 00 30 00 Oct 2 14:02:00 freenas Controller reported scsi ioc terminated tgt 5 SMID 909 loginfo 31080000 Oct 2 14:02:00 freenas mps0: Controller reported scsi ioc terminated tgt 5 SMID 1816 loginfo 31080000 Oct 2 14:02:00 freenas mps0: Controller reported scsi ioc terminated tgt 5 SMID 1934 loginfo 31080000 Oct 2 14:02:00 freenas mps0: (da3:mps0:0:5:0): CAM status: CCB request completed with an error Oct 2 14:02:00 freenas (da3:mps0:0:5:0): Retrying command, 3 more tries remain Oct 2 14:02:00 freenas Controller reported scsi ioc terminated tgt 5 SMID 147 loginfo 31080000 Oct 2 14:02:00 freenas mps0: Controller reported scsi ioc terminated tgt 5 SMID 812 loginfo 31080000 Oct 2 14:02:00 freenas mps0: Controller reported scsi ioc terminated tgt 5 SMID 521 loginfo 31080000 Oct 2 14:02:00 freenas mps0: Controller reported scsi ioc terminated tgt 5 SMID 2072 loginfo 31080000 Oct 2 14:02:00 freenas mps0: Controller reported scsi ioc terminated tgt 5 SMID 1786 loginfo 31080000 Oct 2 14:02:00 freenas (da3:mps0:0:5:0): WRITE(10). CDB: 2a 00 4f 20 6a 58 00 00 28 00 Oct 2 14:02:00 freenas (da3:mps0:0:5:0): CAM status: CCB request completed with an error Oct 2 14:02:00 freenas (da3:mps0:0:5:0): Retrying command, 3 more tries remain Oct 2 14:02:00 freenas (da3:mps0:0:5:0): WRITE(10). CDB: 2a 00 4f 20 6b 08 00 00 30 00 Oct 2 14:02:00 freenas (da3:mps0:0:5:0): CAM status: CCB request completed with an error Oct 2 14:02:00 freenas (da3:mps0:0:5:0): Retrying command, 3 more tries remain Oct 2 14:02:00 freenas (da3:mps0:0:5:0): WRITE(10). CDB: 2a 00 4f 20 6a e0 00 00 28 00 Oct 2 14:02:00 freenas (da3:mps0:0:5:0): CAM status: CCB request completed with an error Oct 2 14:02:00 freenas (da3:mps0:0:5:0): Retrying command, 3 more tries remain Oct 2 14:02:00 freenas (da3:mps0:0:5:0): WRITE(10). CDB: 2a 00 4f 20 6b 38 00 00 28 00 Oct 2 14:02:00 freenas (da3:mps0:0:5:0): CAM status: CCB request completed with an error Oct 2 14:02:00 freenas (da3:mps0:0:5:0): Retrying command, 3 more tries remain Oct 2 14:02:00 freenas (da3:mps0:0:5:0): WRITE(10). CDB: 2a 00 4f 20 6b 90 00 00 30 00 Oct 2 14:02:00 freenas (da3:mps0:0:5:0): CAM status: CCB request completed with an error Oct 2 14:02:00 freenas (da3:mps0:0:5:0): Retrying command, 3 more tries remain Oct 2 14:02:00 freenas (da3:mps0:0:5:0): WRITE(10). CDB: 2a 00 4f 20 6b c0 00 00 28 00 Oct 2 14:02:00 freenas (da3:mps0:0:5:0): CAM status: CCB request completed with an error Oct 2 14:02:00 freenas (da3:mps0:0:5:0): Retrying command, 3 more tries remain Oct 2 14:02:00 freenas (da3:mps0:0:5:0): WRITE(10). CDB: 2a 00 4f 20 6b 68 00 00 28 00 Oct 2 14:02:00 freenas (da3:mps0:0:5:0): CAM status: CCB request completed with an error Oct 2 14:02:00 freenas (da3:mps0:0:5:0): Retrying command, 3 more tries remain Oct 2 14:02:00 freenas (da3:mps0:0:5:0): WRITE(10). CDB: 2a 00 4f 20 6b e8 00 00 30 00 Oct 2 14:02:00 freenas (da3:mps0:0:5:0): CAM status: CCB request completed with an error Oct 2 14:02:01 freenas (da3:mps0:0:5:0): Retrying command, 3 more tries remain Oct 2 14:02:01 freenas (da3:mps0:0:5:0): WRITE(10). CDB: 2a 00 4f 20 6a 80 00 00 30 00 Oct 2 14:02:01 freenas (da3:mps0:0:5:0): CAM status: SCSI Status Error Oct 2 14:02:01 freenas (da3:mps0:0:5:0): SCSI status: Check Condition Oct 2 14:02:01 freenas (da3:mps0:0:5:0): SCSI sense: ILLEGAL REQUEST asc:21,0 (Logical block address out of range) Oct 2 14:02:01 freenas (da3:mps0:0:5:0): Info: 0x4f206a80 Oct 2 14:02:01 freenas (da3:mps0:0:5:0): Error 22, Unretryable error
Latest Smart Output:
Code:
smartctl 7.2 2020-12-30 r5155 [FreeBSD 12.2-RELEASE-p9 amd64] (local build) Copyright (C) 2002-20, Bruce Allen, Christian Franke, www.smartmontools.org === START OF INFORMATION SECTION === Model Family: Western Digital Red Device Model: WDC WD60EFRX-68MYMN1 Serial Number: WD-REDACTED LU WWN Device Id: 5 0014ee 20b559a84 Firmware Version: 82.00A82 User Capacity: 6,001,175,126,016 bytes [6.00 TB] Sector Sizes: 512 bytes logical, 4096 bytes physical Rotation Rate: 5700 rpm Device is: In smartctl database [for details use: -P show] ATA Version is: ACS-2, ACS-3 T13/2161-D revision 3b SATA Version is: SATA 3.1, 6.0 Gb/s (current: 6.0 Gb/s) Local Time is: Mon Oct 4 16:21:41 2021 EDT SMART support is: Available - device has SMART capability. SMART support is: Enabled AAM feature is: Unavailable APM feature is: Unavailable Rd look-ahead is: Enabled Write cache is: Enabled DSN feature is: Unavailable ATA Security is: Disabled, NOT FROZEN [SEC1] Wt Cache Reorder: 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: ( 4784) seconds. Offline data collection capabilities: (0x7b) SMART execute Offline immediate. Auto Offline data collection on/off 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: ( 702) minutes. Conveyance self-test routine recommended polling time: ( 5) minutes. SCT capabilities: (0x303d) SCT Status supported. SCT Error Recovery Control supported. SCT Feature Control supported. SCT Data Table supported. SMART Attributes Data Structure revision number: 16 Vendor Specific SMART Attributes with Thresholds: ID# ATTRIBUTE_NAME FLAGS VALUE WORST THRESH FAIL RAW_VALUE 1 Raw_Read_Error_Rate POSR-K 200 200 051 - 0 3 Spin_Up_Time POS--K 221 190 021 - 7941 4 Start_Stop_Count -O--CK 100 100 000 - 472 5 Reallocated_Sector_Ct PO--CK 200 200 140 - 0 7 Seek_Error_Rate -OSR-K 200 200 000 - 0 9 Power_On_Hours -O--CK 031 031 000 - 50928 10 Spin_Retry_Count -O--CK 100 100 000 - 0 11 Calibration_Retry_Count -O--CK 100 100 000 - 0 12 Power_Cycle_Count -O--CK 100 100 000 - 113 192 Power-Off_Retract_Count -O--CK 200 200 000 - 77 193 Load_Cycle_Count -O--CK 187 187 000 - 40408 194 Temperature_Celsius -O---K 108 095 000 - 44 196 Reallocated_Event_Count -O--CK 200 200 000 - 0 197 Current_Pending_Sector -O--CK 200 200 000 - 0 198 Offline_Uncorrectable ----CK 100 253 000 - 0 199 UDMA_CRC_Error_Count -O--CK 200 200 000 - 0 200 Multi_Zone_Error_Rate ---R-- 200 200 000 - 0 ||||||_ K auto-keep |||||__ C event count ||||___ R error rate |||____ S speed/performance ||_____ O updated online |______ P prefailure warning General Purpose Log Directory Version 1 SMART Log Directory Version 1 [multi-sector log support] Address Access R/W Size Description 0x00 GPL,SL R/O 1 Log Directory 0x01 SL R/O 1 Summary SMART error log 0x02 SL R/O 5 Comprehensive SMART error log 0x03 GPL R/O 6 Ext. Comprehensive SMART error log 0x06 SL R/O 1 SMART self-test log 0x07 GPL R/O 1 Extended self-test log 0x09 SL R/W 1 Selective self-test log 0x10 GPL R/O 1 NCQ Command Error log 0x11 GPL R/O 1 SATA Phy Event Counters log 0x21 GPL R/O 1 Write stream error log 0x22 GPL R/O 1 Read stream error log 0x30 GPL,SL R/O 9 IDENTIFY DEVICE data log 0x80-0x9f GPL,SL R/W 16 Host vendor specific log 0xa0-0xa7 GPL,SL VS 16 Device vendor specific log 0xa8-0xb6 GPL,SL VS 1 Device vendor specific log 0xb7 GPL,SL VS 40 Device vendor specific log 0xbd GPL,SL VS 1 Device vendor specific log 0xc0 GPL,SL VS 1 Device vendor specific log 0xc1 GPL VS 93 Device vendor specific log 0xe0 GPL,SL R/W 1 SCT Command/Status 0xe1 GPL,SL R/W 1 SCT Data Transfer SMART Extended Comprehensive Error Log Version: 1 (6 sectors) Device Error Count: 6 CR = Command Register FEATR = Features Register COUNT = Count (was: Sector Count) Register LBA_48 = Upper bytes of LBA High/Mid/Low Registers ] ATA-8 LH = LBA High (was: Cylinder High) Register ] LBA LM = LBA Mid (was: Cylinder Low) Register ] Register LL = LBA Low (was: Sector Number) Register ] DV = Device (was: Device/Head) Register DC = Device Control Register ER = Error register ST = Status register Powered_Up_Time is measured from power on, and printed as DDd+hh:mm:SS.sss where DD=days, hh=hours, mm=minutes, SS=sec, and sss=millisec. It "wraps" after 49.710 days. Error 6 [5] occurred at disk power-on lifetime: 50878 hours (2119 days + 22 hours) When the command that caused the error occurred, the device was active or idle. After command completion occurred, registers were: ER -- ST COUNT LBA_48 LH LM LL DV DC -- -- -- == -- == == == -- -- -- -- -- 10 -- 51 00 00 00 00 4f 20 6a 80 40 00 Error: IDNF at LBA = 0x4f206a80 = 1327524480 Commands leading to the command that caused the error were: CR FEATR COUNT LBA_48 LH LM LL DV DC Powered_Up_Time Command/Feature_Name -- == -- == -- == == == -- -- -- -- -- --------------- -------------------- 61 00 30 00 00 00 00 4f 20 6a 80 40 00 7d+03:19:07.767 WRITE FPDMA QUEUED ea 00 00 00 00 00 00 00 00 00 00 40 00 7d+03:19:06.998 FLUSH CACHE EXT 61 00 08 00 10 00 02 ba a0 f4 00 40 00 7d+03:19:06.997 WRITE FPDMA QUEUED 61 00 08 00 00 00 02 ba a0 f2 00 40 00 7d+03:19:06.997 WRITE FPDMA QUEUED 61 00 08 00 08 00 00 00 40 04 00 40 00 7d+03:19:06.997 WRITE FPDMA QUEUED Error 5 [4] occurred at disk power-on lifetime: 50677 hours (2111 days + 13 hours) When the command that caused the error occurred, the device was active or idle. After command completion occurred, registers were: ER -- ST COUNT LBA_48 LH LM LL DV DC -- -- -- == -- == == == -- -- -- -- -- 10 -- 51 00 00 00 02 14 e5 9d c0 40 00 Error: IDNF at LBA = 0x214e59dc0 = 8940527040 Commands leading to the command that caused the error were: CR FEATR COUNT LBA_48 LH LM LL DV DC Powered_Up_Time Command/Feature_Name -- == -- == -- == == == -- -- -- -- -- --------------- -------------------- 61 00 08 00 00 00 02 14 e5 9d c0 40 00 41d+02:52:12.844 WRITE FPDMA QUEUED ea 00 00 00 00 00 00 00 00 00 00 40 00 41d+02:51:52.870 FLUSH CACHE EXT 61 00 08 00 00 00 02 ba a0 f4 48 40 00 41d+02:51:52.869 WRITE FPDMA QUEUED 61 00 08 00 10 00 02 ba a0 f2 48 40 00 41d+02:51:52.869 WRITE FPDMA QUEUED 61 00 08 00 08 00 00 00 40 04 48 40 00 41d+02:51:52.869 WRITE FPDMA QUEUED Error 4 [3] occurred at disk power-on lifetime: 45881 hours (1911 days + 17 hours) When the command that caused the error occurred, the device was active or idle. After command completion occurred, registers were: ER -- ST COUNT LBA_48 LH LM LL DV DC -- -- -- == -- == == == -- -- -- -- -- 40 -- 51 00 00 00 02 16 47 8b f0 40 00 Error: UNC at LBA = 0x216478bf0 = 8963722224 Commands leading to the command that caused the error were: CR FEATR COUNT LBA_48 LH LM LL DV DC Powered_Up_Time Command/Feature_Name -- == -- == -- == == == -- -- -- -- -- --------------- -------------------- 60 00 30 00 00 00 02 16 47 8b f0 40 00 3d+05:45:24.873 READ FPDMA QUEUED 60 00 28 00 00 00 02 16 47 8b 98 40 00 3d+05:45:24.832 READ FPDMA QUEUED 60 00 30 00 00 00 02 16 47 8b 68 40 00 3d+05:45:24.832 READ FPDMA QUEUED 60 00 28 00 00 00 02 16 47 8b 40 40 00 3d+05:45:24.832 READ FPDMA QUEUED 60 00 28 00 00 00 02 16 47 8b 10 40 00 3d+05:45:24.831 READ FPDMA QUEUED Error 3 [2] occurred at disk power-on lifetime: 44438 hours (1851 days + 14 hours) When the command that caused the error occurred, the device was active or idle. After command completion occurred, registers were: ER -- ST COUNT LBA_48 LH LM LL DV DC -- -- -- == -- == == == -- -- -- -- -- 40 -- 51 00 00 00 02 5a 4c 71 00 40 00 Error: UNC at LBA = 0x25a4c7100 = 10104893696 Commands leading to the command that caused the error were: CR FEATR COUNT LBA_48 LH LM LL DV DC Powered_Up_Time Command/Feature_Name -- == -- == -- == == == -- -- -- -- -- --------------- -------------------- 60 00 30 00 00 00 02 5a 4c 71 00 40 00 7d+06:54:25.014 READ FPDMA QUEUED 60 00 28 00 00 00 02 5a 4c 70 a8 40 00 7d+06:54:25.014 READ FPDMA QUEUED 60 00 30 00 00 00 02 5a 4c 70 78 40 00 7d+06:54:25.013 READ FPDMA QUEUED 60 00 28 00 08 00 02 5a 4c 70 50 40 00 7d+06:54:25.013 READ FPDMA QUEUED 60 00 28 00 00 00 02 5a 4c 70 20 40 00 7d+06:54:25.013 READ FPDMA QUEUED Error 2 [1] occurred at disk power-on lifetime: 43391 hours (1807 days + 23 hours) When the command that caused the error occurred, the device was active or idle. After command completion occurred, registers were: ER -- ST COUNT LBA_48 LH LM LL DV DC -- -- -- == -- == == == -- -- -- -- -- 40 -- 51 00 00 00 01 70 9d 21 c0 40 00 Error: UNC at LBA = 0x1709d21c0 = 6184313280 Commands leading to the command that caused the error were: CR FEATR COUNT LBA_48 LH LM LL DV DC Powered_Up_Time Command/Feature_Name -- == -- == -- == == == -- -- -- -- -- --------------- -------------------- 60 00 30 00 00 00 01 70 9d 21 c0 40 00 8d+04:08:24.792 READ FPDMA QUEUED 60 00 28 00 00 00 01 70 9d 21 98 40 00 8d+04:08:24.777 READ FPDMA QUEUED 60 00 28 00 00 00 01 70 9d 21 68 40 00 8d+04:08:24.777 READ FPDMA QUEUED 60 00 28 00 00 00 01 70 9d 1f 20 40 00 8d+04:08:24.776 READ FPDMA QUEUED 60 00 28 00 00 00 01 70 9d 21 10 40 00 8d+04:08:24.776 READ FPDMA QUEUED Error 1 [0] occurred at disk power-on lifetime: 40486 hours (1686 days + 22 hours) When the command that caused the error occurred, the device was active or idle. After command completion occurred, registers were: ER -- ST COUNT LBA_48 LH LM LL DV DC -- -- -- == -- == == == -- -- -- -- -- 40 -- 51 00 00 00 02 b7 0b 30 d8 40 00 Error: UNC at LBA = 0x2b70b30d8 = 11660898520 Commands leading to the command that caused the error were: CR FEATR COUNT LBA_48 LH LM LL DV DC Powered_Up_Time Command/Feature_Name -- == -- == -- == == == -- -- -- -- -- --------------- -------------------- 60 00 58 00 08 00 02 b7 0b 89 f8 40 00 33d+00:38:34.307 READ FPDMA QUEUED 60 00 58 00 00 00 02 b7 0b 30 d0 40 00 33d+00:38:34.296 READ FPDMA QUEUED 60 00 58 00 08 00 02 b7 0a d7 c0 40 00 33d+00:38:34.284 READ FPDMA QUEUED 60 00 60 00 00 00 02 b7 0a 7e 88 40 00 33d+00:38:34.284 READ FPDMA QUEUED 60 00 58 00 00 00 02 b7 0a 25 48 40 00 33d+00:38:34.270 READ FPDMA QUEUED SMART Extended Self-test Log Version: 1 (1 sectors) Num Test_Description Status Remaining LifeTime(hours) LBA_of_first_error # 1 Extended offline Completed without error 00% 49665 - # 2 Extended offline Completed without error 00% 49598 - # 3 Extended offline Completed without error 00% 46102 - # 4 Extended offline Completed without error 00% 18012 - # 5 Extended offline Completed without error 00% 177 - # 6 Extended offline Completed without error 00% 127 - # 7 Extended offline Completed without error 00% 90 - # 8 Extended offline Completed without error 00% 55 - # 9 Extended offline Completed without error 00% 12 - #10 Short offline Completed without error 00% 0 - #11 Conveyance offline Completed without error 00% 0 - SMART Selective self-test log data structure revision number 1 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. SCT Status Version: 3 SCT Version (vendor specific): 258 (0x0102) Device State: Active (0) Current Temperature: 44 Celsius Power Cycle Min/Max Temperature: 38/47 Celsius Lifetime Min/Max Temperature: 2/57 Celsius Under/Over Temperature Limit Count: 0/0 Vendor specific: 00 01 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 SCT Temperature History Version: 2 Temperature Sampling Period: 1 minute Temperature Logging Interval: 1 minute Min/Max recommended Temperature: 0/60 Celsius Min/Max Temperature Limit: -41/85 Celsius Temperature History Size (Index): 478 (218) Index Estimated Time Temperature Celsius 219 2021-10-04 08:24 44 ************************* ... ..(476 skipped). .. ************************* 218 2021-10-04 16:21 44 ************************* SCT Error Recovery Control: Read: 70 (7.0 seconds) Write: 70 (7.0 seconds) Device Statistics (GP/SMART Log 0x04) not supported Pending Defects log (GP Log 0x0c) not supported SATA Phy Event Counters (GP Log 0x11) ID Size Value Description 0x0001 2 0 Command failed due to ICRC error 0x0002 2 0 R_ERR response for data FIS 0x0003 2 0 R_ERR response for device-to-host data FIS 0x0004 2 0 R_ERR response for host-to-device data FIS 0x0005 2 0 R_ERR response for non-data FIS 0x0006 2 0 R_ERR response for device-to-host non-data FIS 0x0007 2 0 R_ERR response for host-to-device non-data FIS 0x0008 2 0 Device-to-host non-data FIS retries 0x0009 2 1 Transition from drive PhyRdy to drive PhyNRdy 0x000a 2 4 Device-to-host register FISes sent due to a COMRESET 0x000b 2 0 CRC errors within host-to-device FIS 0x000f 2 0 R_ERR response for host-to-device data FIS, CRC 0x0012 2 0 R_ERR response for host-to-device non-data FIS, CRC 0x8000 4 797757 Vendor specific