Hi all,
I am having a difficult to explain problem with my main pool on a TrueNAS 12U8 system. The setup has been functioning without a problem for more than four years now, I have grown complacent and I didn't setup a backup - it is a home installation and I was trying to minimise the machines in use. Otherwise I am a long time user of various ZFS-supporting systems, so far I have never had a problem related to ZFS itself; this one appears to be the first.
The system in question has a SAS adapter as follows:
mps0: <Avago Technologies (LSI) SAS2308> port 0x4000-0x40ff mem 0xf3540000-0xf354ffff,0xf3500000-0xf353ffff irq 17 at device 0.0 on pci2
mps0: Firmware: 20.00.07.00, Driver: 21.02.00.00-fbsd
mps0: IOCCapabilities: 5a85c<ScsiTaskFull,DiagTrace,SnapBuf,EEDP,TransRetry,EventReplay,MSIXIndex,HostDisc>
da6 at mps0 bus 0 scbus0 target 10 lun 0
da4 at mps0 bus 0 scbus0 target 5 lun 0
da3 at mps0 bus 0 scbus0 target 3 lun 0
da1 at mps0 bus 0 scbus0 target 1 lun 0
da2 at mps0 bus 0 scbus0 target 2 lun 0
da0 at mps0 bus 0 scbus0 target 0 lun 0
da5 at mps0 bus 0 scbus0 target 9 lun 0
It came pre-flashed with the necessary firmware and I haven't had any problems with it. Four of the disks are 4TB Seagate IronWolf ST4000VN008-2DR166, forming the principal RAID-Z pool dix; the other four were other enterprise-grade 2TB disks in another RAID-Z pool (I didn't use the latter, one of the 2TB disks was showing errors, so I destroyed the pool and removed the bad disk).
Today I noticed that I can't see the smb shares and iSCSI volumes served by this TrueNAS device. The main data pool, dix, was not available. The disks, all of them, appeared online, 'smartctl -a ...' gave me passed results on all of them. 'zpool import' lists the pool:
# zpool import
pool: dix
id: 11829383913552013861
state: ONLINE
action: The pool can be imported using its name or numeric identifier.
config:
dix ONLINE
raidz1-0 ONLINE
gptid/18a3403b-1a2c-11eb-84f3-00224d4d87e1 ONLINE
gptid/194759fc-1a2c-11eb-84f3-00224d4d87e1 ONLINE
gptid/1968aee9-1a2c-11eb-84f3-00224d4d87e1 ONLINE
gptid/1957913f-1a2c-11eb-84f3-00224d4d87e1 ONLINE
cache
gptid/188591a4-1a2c-11eb-84f3-00224d4d87e1
Any attempt to import a pool, by name or id, fails with:
# zpool import -f dix
cannot import 'dix': I/O error
Destroy and re-create the pool from
a backup source.
'zdb -e -C dix' shows reasonable values, however, /var/log/console.log contains sequences like:
...
Apr 3 17:01:47 truenas Beginning pools import
Apr 3 17:01:47 truenas Importing dix
Apr 3 17:01:47 truenas vdev.c:129:vdev_dbgmsg(): disk vdev '/dev/gptid/18a3403b-1a2c-11eb-84f3-00224d4d87e1': best uberblock found for spa $import. txg 8687697
Apr 3 17:01:47 truenas spa_misc.c:416:spa_load_note(): spa_load($import, config untrusted): using uberblock with txg=8687697
Apr 3 17:01:47 truenas spa.c:8229:spa_async_request(): spa=$import async request task=4096
Apr 3 17:01:47 truenas spa.c:8229:spa_async_request(): spa=$import async request task=2048
Apr 3 17:01:47 truenas spa_misc.c:416:spa_load_note(): spa_load($import, config trusted): LOADED
Apr 3 17:01:47 truenas spa_misc.c:416:spa_load_note(): spa_load($import, config trusted): UNLOADING
Apr 3 17:01:47 truenas spa.c:6032:spa_import(): spa_import: importing dix
Apr 3 17:01:47 truenas spa_misc.c:416:spa_load_note(): spa_load(dix, config trusted): LOADING
Apr 3 17:01:47 truenas vdev.c:129:vdev_dbgmsg(): disk vdev '/dev/gptid/194759fc-1a2c-11eb-84f3-00224d4d87e1': best uberblock found for spa dix. txg 8687697
Apr 3 17:01:47 truenas spa_misc.c:416:spa_load_note(): spa_load(dix, config untrusted): using uberblock with txg=8687697
Apr 3 17:01:47 truenas spa.c:8229:spa_async_request(): spa=dix async request task=4096
Apr 3 17:01:47 truenas spa_misc.c:416:spa_load_note(): spa_load(dix, config trusted): read 931 log space maps (931 total blocks - blksz = 131072 bytes) in 5131 ms
Apr 3 17:01:47 truenas metaslab.c:2422:metaslab_load_impl(): metaslab_load: txg 0, spa dix, vdev_id 0, ms_id 313, smp_length 487400, unflushed_allocs 13746176, unflushed_frees 10911744, freed 0, defer 0 + 0, unloaded time 33298 ms, loading_time 111 ms, ms_max_size 5110702080, ma
Apr 3 17:01:47 truenas metaslab.c:2422:metaslab_load_impl(): metaslab_load: txg 0, spa dix, vdev_id 0, ms_id 314, smp_length 408688, unflushed_allocs 29671424, unflushed_frees 13467648, freed 0, defer 0 + 0, unloaded time 33594 ms, loading_time 97 ms, ms_max_size 2306498560, max
Apr 3 17:01:47 truenas spa_misc.c:416:spa_load_note(): spa_load(dix, config trusted): spa_load_verify found 3 metadata errors and 0 data errors
Apr 3 17:01:47 truenas spa_misc.c:401:spa_load_failed(): spa_load(dix, config trusted): FAILED: spa_load_verify failed [error=5]
Apr 3 17:01:47 truenas spa_misc.c:416:spa_load_note(): spa_load(dix, config trusted): UNLOADING
Apr 3 17:01:47 truenas spa_misc.c:416:spa_load_note(): spa_load(dix, config trusted): spa_load_retry: rewind, max txg: 8687696
Apr 3 17:01:47 truenas spa_misc.c:416:spa_load_note(): spa_load(dix, config trusted): LOADING
....
apparently for each of the 4TB Seagate disks comprising the dix pool; it would appear that the system was rebooted a couple of days ago - which I haven't done, there was no brown- or black-out as all my other machines with no UPS are still running with long uptimes.
I am running 'zpool import -FX dix' at the moment, 15 minutes with no output yet.
I am having a difficult to explain problem with my main pool on a TrueNAS 12U8 system. The setup has been functioning without a problem for more than four years now, I have grown complacent and I didn't setup a backup - it is a home installation and I was trying to minimise the machines in use. Otherwise I am a long time user of various ZFS-supporting systems, so far I have never had a problem related to ZFS itself; this one appears to be the first.
The system in question has a SAS adapter as follows:
mps0: <Avago Technologies (LSI) SAS2308> port 0x4000-0x40ff mem 0xf3540000-0xf354ffff,0xf3500000-0xf353ffff irq 17 at device 0.0 on pci2
mps0: Firmware: 20.00.07.00, Driver: 21.02.00.00-fbsd
mps0: IOCCapabilities: 5a85c<ScsiTaskFull,DiagTrace,SnapBuf,EEDP,TransRetry,EventReplay,MSIXIndex,HostDisc>
da6 at mps0 bus 0 scbus0 target 10 lun 0
da4 at mps0 bus 0 scbus0 target 5 lun 0
da3 at mps0 bus 0 scbus0 target 3 lun 0
da1 at mps0 bus 0 scbus0 target 1 lun 0
da2 at mps0 bus 0 scbus0 target 2 lun 0
da0 at mps0 bus 0 scbus0 target 0 lun 0
da5 at mps0 bus 0 scbus0 target 9 lun 0
It came pre-flashed with the necessary firmware and I haven't had any problems with it. Four of the disks are 4TB Seagate IronWolf ST4000VN008-2DR166, forming the principal RAID-Z pool dix; the other four were other enterprise-grade 2TB disks in another RAID-Z pool (I didn't use the latter, one of the 2TB disks was showing errors, so I destroyed the pool and removed the bad disk).
Today I noticed that I can't see the smb shares and iSCSI volumes served by this TrueNAS device. The main data pool, dix, was not available. The disks, all of them, appeared online, 'smartctl -a ...' gave me passed results on all of them. 'zpool import' lists the pool:
# zpool import
pool: dix
id: 11829383913552013861
state: ONLINE
action: The pool can be imported using its name or numeric identifier.
config:
dix ONLINE
raidz1-0 ONLINE
gptid/18a3403b-1a2c-11eb-84f3-00224d4d87e1 ONLINE
gptid/194759fc-1a2c-11eb-84f3-00224d4d87e1 ONLINE
gptid/1968aee9-1a2c-11eb-84f3-00224d4d87e1 ONLINE
gptid/1957913f-1a2c-11eb-84f3-00224d4d87e1 ONLINE
cache
gptid/188591a4-1a2c-11eb-84f3-00224d4d87e1
Any attempt to import a pool, by name or id, fails with:
# zpool import -f dix
cannot import 'dix': I/O error
Destroy and re-create the pool from
a backup source.
'zdb -e -C dix' shows reasonable values, however, /var/log/console.log contains sequences like:
...
Apr 3 17:01:47 truenas Beginning pools import
Apr 3 17:01:47 truenas Importing dix
Apr 3 17:01:47 truenas vdev.c:129:vdev_dbgmsg(): disk vdev '/dev/gptid/18a3403b-1a2c-11eb-84f3-00224d4d87e1': best uberblock found for spa $import. txg 8687697
Apr 3 17:01:47 truenas spa_misc.c:416:spa_load_note(): spa_load($import, config untrusted): using uberblock with txg=8687697
Apr 3 17:01:47 truenas spa.c:8229:spa_async_request(): spa=$import async request task=4096
Apr 3 17:01:47 truenas spa.c:8229:spa_async_request(): spa=$import async request task=2048
Apr 3 17:01:47 truenas spa_misc.c:416:spa_load_note(): spa_load($import, config trusted): LOADED
Apr 3 17:01:47 truenas spa_misc.c:416:spa_load_note(): spa_load($import, config trusted): UNLOADING
Apr 3 17:01:47 truenas spa.c:6032:spa_import(): spa_import: importing dix
Apr 3 17:01:47 truenas spa_misc.c:416:spa_load_note(): spa_load(dix, config trusted): LOADING
Apr 3 17:01:47 truenas vdev.c:129:vdev_dbgmsg(): disk vdev '/dev/gptid/194759fc-1a2c-11eb-84f3-00224d4d87e1': best uberblock found for spa dix. txg 8687697
Apr 3 17:01:47 truenas spa_misc.c:416:spa_load_note(): spa_load(dix, config untrusted): using uberblock with txg=8687697
Apr 3 17:01:47 truenas spa.c:8229:spa_async_request(): spa=dix async request task=4096
Apr 3 17:01:47 truenas spa_misc.c:416:spa_load_note(): spa_load(dix, config trusted): read 931 log space maps (931 total blocks - blksz = 131072 bytes) in 5131 ms
Apr 3 17:01:47 truenas metaslab.c:2422:metaslab_load_impl(): metaslab_load: txg 0, spa dix, vdev_id 0, ms_id 313, smp_length 487400, unflushed_allocs 13746176, unflushed_frees 10911744, freed 0, defer 0 + 0, unloaded time 33298 ms, loading_time 111 ms, ms_max_size 5110702080, ma
Apr 3 17:01:47 truenas metaslab.c:2422:metaslab_load_impl(): metaslab_load: txg 0, spa dix, vdev_id 0, ms_id 314, smp_length 408688, unflushed_allocs 29671424, unflushed_frees 13467648, freed 0, defer 0 + 0, unloaded time 33594 ms, loading_time 97 ms, ms_max_size 2306498560, max
Apr 3 17:01:47 truenas spa_misc.c:416:spa_load_note(): spa_load(dix, config trusted): spa_load_verify found 3 metadata errors and 0 data errors
Apr 3 17:01:47 truenas spa_misc.c:401:spa_load_failed(): spa_load(dix, config trusted): FAILED: spa_load_verify failed [error=5]
Apr 3 17:01:47 truenas spa_misc.c:416:spa_load_note(): spa_load(dix, config trusted): UNLOADING
Apr 3 17:01:47 truenas spa_misc.c:416:spa_load_note(): spa_load(dix, config trusted): spa_load_retry: rewind, max txg: 8687696
Apr 3 17:01:47 truenas spa_misc.c:416:spa_load_note(): spa_load(dix, config trusted): LOADING
....
apparently for each of the 4TB Seagate disks comprising the dix pool; it would appear that the system was rebooted a couple of days ago - which I haven't done, there was no brown- or black-out as all my other machines with no UPS are still running with long uptimes.
I am running 'zpool import -FX dix' at the moment, 15 minutes with no output yet.
