Strange pool offline emails

[websmith]

Hi,

Today I got two emails from one of my truenas servers.

First one stated:

Code:

New alerts:
* Pool tank2 state is OFFLINE: None

Current alerts:
* Pool tank2 state is OFFLINE: None

Then 1 minute after I received:

Code:

The following alert has been cleared:
* Pool tank2 state is OFFLINE: None

I have looked throught the log files on the server and also done a zpool status:

Show : zpool status

Code:

 pool: tank2
 state: ONLINE
status: Some supported features are not enabled on the pool. The pool can
        still be used, but some features are unavailable.
action: Enable all features using 'zpool upgrade'. Once this is done,
        the pool may no longer be accessible by software that does not support
        the features. See zpool-features(5) for details.
  scan: scrub repaired 0B in 03:14:35 with 0 errors on Sun Dec  5 03:14:40 2021
config:

        NAME                                            STATE     READ WRITE CKSUM
        tank2                                           ONLINE       0     0     0
          mirror-0                                      ONLINE       0     0     0
            gptid/0d932ec4-62c9-11e9-8f21-a0369f09f4ea  ONLINE       0     0     0
            gptid/0e519d79-62c9-11e9-8f21-a0369f09f4ea  ONLINE       0     0     0
        logs
          gpt/tank2_log                                 ONLINE       0     0     0

errors: No known data errors

Show : smart status

Code:

root@nas:/var/log # smartctl -a /dev/ada2
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-68L0BN1
Serial Number:    WD-WX11DA8DHFV5
LU WWN Device Id: 5 0014ee 2bb432b67
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:    Sat Dec 11 00:25:02 2021 CET
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:                ( 2804) 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:        ( 682) 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          FLAG     VALUE WORST THRESH TYPE      UPDATED  WHEN_FAILED RAW_VALUE
  1 Raw_Read_Error_Rate     0x002f   200   200   051    Pre-fail  Always       -       0
  3 Spin_Up_Time            0x0027   234   197   021    Pre-fail  Always       -       7266
  4 Start_Stop_Count        0x0032   100   100   000    Old_age   Always       -       188
  5 Reallocated_Sector_Ct   0x0033   200   200   140    Pre-fail  Always       -       0
  7 Seek_Error_Rate         0x002e   200   200   000    Old_age   Always       -       0
  9 Power_On_Hours          0x0032   069   069   000    Old_age   Always       -       22997
 10 Spin_Retry_Count        0x0032   100   100   000    Old_age   Always       -       0
 11 Calibration_Retry_Count 0x0032   100   100   000    Old_age   Always       -       0
 12 Power_Cycle_Count       0x0032   100   100   000    Old_age   Always       -       147
192 Power-Off_Retract_Count 0x0032   200   200   000    Old_age   Always       -       108
193 Load_Cycle_Count        0x0032   199   199   000    Old_age   Always       -       5772
194 Temperature_Celsius     0x0022   114   106   000    Old_age   Always       -       38
196 Reallocated_Event_Count 0x0032   200   200   000    Old_age   Always       -       0
197 Current_Pending_Sector  0x0032   200   200   000    Old_age   Always       -       0
198 Offline_Uncorrectable   0x0030   100   253   000    Old_age   Offline      -       0
199 UDMA_CRC_Error_Count    0x0032   200   200   000    Old_age   Always       -       0
200 Multi_Zone_Error_Rate   0x0008   200   200   000    Old_age   Offline      -       0

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  Extended offline    Completed without error       00%     22777         -
# 2  Extended offline    Completed without error       00%     22058         -
# 3  Extended offline    Completed without error       00%     21313         -
# 4  Extended offline    Completed without error       00%     20594         -
# 5  Extended offline    Completed without error       00%     19851         -
# 6  Extended offline    Completed without error       00%     19108         -
# 7  Extended offline    Completed without error       00%     18389         -
# 8  Extended offline    Completed without error       00%     17645         -
# 9  Extended offline    Completed without error       00%     16926         -
#10  Extended offline    Completed without error       00%     16184         -
#11  Extended offline    Completed without error       00%     15514         -
#12  Extended offline    Completed without error       00%     14771         -
#13  Extended offline    Completed without error       00%     14027         -
#14  Extended offline    Completed without error       00%     13310         -
#15  Extended offline    Completed without error       00%     12568         -
#16  Extended offline    Completed without error       00%     11848         -
#17  Extended offline    Completed without error       00%     11105         -
#18  Extended offline    Completed without error       00%      9643         -
#19  Extended offline    Completed without error       00%      8900         -
#20  Extended offline    Completed without error       00%      8181         -
#21  Extended offline    Completed without error       00%      7439         -

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.

Code:

root@nas:/var/log # smartctl -a /dev/ada4
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-68L0BN1
Serial Number:    WD-WX11DA8DHSD2
LU WWN Device Id: 5 0014ee 265ed8ac1
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:    Sat Dec 11 00:26:09 2021 CET
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:                ( 4604) 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:        ( 700) 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          FLAG     VALUE WORST THRESH TYPE      UPDATED  WHEN_FAILED RAW_VALUE
  1 Raw_Read_Error_Rate     0x002f   200   200   051    Pre-fail  Always       -       0
  3 Spin_Up_Time            0x0027   234   197   021    Pre-fail  Always       -       7300
  4 Start_Stop_Count        0x0032   100   100   000    Old_age   Always       -       188
  5 Reallocated_Sector_Ct   0x0033   200   200   140    Pre-fail  Always       -       0
  7 Seek_Error_Rate         0x002e   200   200   000    Old_age   Always       -       0
  9 Power_On_Hours          0x0032   069   069   000    Old_age   Always       -       22980
 10 Spin_Retry_Count        0x0032   100   100   000    Old_age   Always       -       0
 11 Calibration_Retry_Count 0x0032   100   100   000    Old_age   Always       -       0
 12 Power_Cycle_Count       0x0032   100   100   000    Old_age   Always       -       147
192 Power-Off_Retract_Count 0x0032   200   200   000    Old_age   Always       -       111
193 Load_Cycle_Count        0x0032   199   199   000    Old_age   Always       -       5793
194 Temperature_Celsius     0x0022   111   103   000    Old_age   Always       -       41
196 Reallocated_Event_Count 0x0032   200   200   000    Old_age   Always       -       0
197 Current_Pending_Sector  0x0032   200   200   000    Old_age   Always       -       0
198 Offline_Uncorrectable   0x0030   100   253   000    Old_age   Offline      -       0
199 UDMA_CRC_Error_Count    0x0032   200   200   000    Old_age   Always       -       0
200 Multi_Zone_Error_Rate   0x0008   200   200   000    Old_age   Offline      -       0

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  Extended offline    Completed without error       00%     22760         -
# 2  Extended offline    Completed without error       00%     22041         -
# 3  Extended offline    Completed without error       00%     21297         -
# 4  Extended offline    Completed without error       00%     20578         -
# 5  Extended offline    Completed without error       00%     19834         -
# 6  Extended offline    Completed without error       00%     19091         -
# 7  Extended offline    Completed without error       00%     18372         -
# 8  Extended offline    Completed without error       00%     17629         -
# 9  Extended offline    Completed without error       00%     16909         -
#10  Extended offline    Completed without error       00%     16168         -
#11  Extended offline    Completed without error       00%     15497         -
#12  Extended offline    Completed without error       00%     14754         -
#13  Extended offline    Completed without error       00%     14011         -
#14  Extended offline    Completed without error       00%     13293         -
#15  Extended offline    Completed without error       00%     12551         -
#16  Extended offline    Completed without error       00%     11832         -
#17  Extended offline    Completed without error       00%     11089         -
#18  Extended offline    Completed without error       00%      9627         -
#19  Extended offline    Completed without error       00%      8884         -
#20  Extended offline    Completed without error       00%      8164         -
#21  Extended offline    Completed without error       00%      7422         -

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.

So everything seems to be in order - at least it looks "normal" - I am aware that running with just one drive for ZIL is probably not good, but its good enough for me

So anything else I can look in to find out why truenas suddenly decided that either my pool was offline, or sent wrong mails?

I am a bit scared now, since I tend to take mails like this very serious, but since everything seems to be okay I don't know what to do.

Thanks in advance

 

[Samuel Tai]

Are there any events in zpool history and zpool events at the same times as your e-mails?

 

[websmith]

This is what gets closest - I dont know where to see the log for when it sent the mail - but in my mail client I got the OFFLINE mail @ 19:06 and the ONLINE mail @ 19:07

Show : zpool events -v

Dec 10 2021 19:06:18.627856567 sysevent.fs.zfs.history_event
version = 0x0
class = "sysevent.fs.zfs.history_event"
pool = "tank2"
pool_guid = 0xaec11512e5b5d4a3
pool_state = 0x0
pool_context = 0x0
history_hostname = "nas.root.dom"
history_dsname = "tank2/backup/esxi_nfs/%recv"
history_internal_str = " "
history_internal_name = "receive"
history_dsid = 0xd48c
history_txg = 0x111456b
history_time = 0x61b3971a
time = 0x61b3971a 0x256c54b7
eid = 0x53b6

Dec 10 2021 19:06:18.914875412 sysevent.fs.zfs.history_event
version = 0x0
class = "sysevent.fs.zfs.history_event"
pool = "tank2"
pool_guid = 0xaec11512e5b5d4a3
pool_state = 0x0
pool_context = 0x0
history_hostname = "nas.root.dom"
history_dsname = "tank2/backup/esxi_nfs"
history_internal_str = "sharesmb=off"
history_internal_name = "inherit"
history_dsid = 0xbedc
history_txg = 0x111456c
history_time = 0x61b3971a
time = 0x61b3971a 0x3687e414
eid = 0x53b7

Dec 10 2021 19:06:18.914875412 sysevent.fs.zfs.history_event
version = 0x0
class = "sysevent.fs.zfs.history_event"
pool = "tank2"
pool_guid = 0xaec11512e5b5d4a3
pool_state = 0x0
pool_context = 0x0
history_hostname = "nas.root.dom"
history_dsname = "tank2/backup/esxi_nfs"
history_internal_str = "sharenfs=off"
history_internal_name = "inherit"
history_dsid = 0xbedc
history_txg = 0x111456c
history_time = 0x61b3971a
time = 0x61b3971a 0x3687e414
eid = 0x53b8

Dec 10 2021 19:06:27.964851199 sysevent.fs.zfs.history_event
version = 0x0
class = "sysevent.fs.zfs.history_event"
pool = "tank2"
pool_guid = 0xaec11512e5b5d4a3
pool_state = 0x0
pool_context = 0x0
history_hostname = "nas.root.dom"
history_dsname = "tank2/backup/esxi_nfs/%recv"
history_internal_str = "snap=auto-2021-12-10_19-00"
history_internal_name = "finish receiving"
history_dsid = 0xd48c
history_txg = 0x1114573
history_time = 0x61b39723
time = 0x61b39723 0x398275ff
eid = 0x53b9

Dec 10 2021 19:06:28.061850890 sysevent.fs.zfs.history_event
version = 0x0
class = "sysevent.fs.zfs.history_event"
pool = "tank2"
pool_guid = 0xaec11512e5b5d4a3
pool_state = 0x0
pool_context = 0x0
history_hostname = "nas.root.dom"
history_dsname = "tank2/backup/esxi_nfs/%recv"
history_internal_str = "parent=esxi_nfs"
history_internal_name = "clone swap"
history_dsid = 0xd48c
history_txg = 0x1114573
history_time = 0x61b39724
time = 0x61b39724 0x3afc50a
eid = 0x53ba

Dec 10 2021 19:06:28.065850819 sysevent.fs.zfs.history_event
version = 0x0
class = "sysevent.fs.zfs.history_event"
pool = "tank2"
pool_guid = 0xaec11512e5b5d4a3
pool_state = 0x0
pool_context = 0x0
history_hostname = "nas.root.dom"
history_dsname = "tank2/backup/esxi_nfs@auto-2021-12-10_19-00"
history_internal_str = " "
history_internal_name = "snapshot"
history_dsid = 0xc879
history_txg = 0x1114573
history_time = 0x61b39724
time = 0x61b39724 0x3eccdc3
eid = 0x53bb

Dec 10 2021 19:06:28.068869532 sysevent.fs.zfs.history_event
version = 0x0
class = "sysevent.fs.zfs.history_event"
pool = "tank2"
pool_guid = 0xaec11512e5b5d4a3
pool_state = 0x0
pool_context = 0x0
history_hostname = "nas.root.dom"
history_dsname = "tank2/backup/esxi_nfs/%recv"
history_internal_str = "(bptree, mintxg=17908389)"
history_internal_name = "destroy"
history_dsid = 0xd48c
history_txg = 0x1114573
history_time = 0x61b39724
time = 0x61b39724 0x41add9c
eid = 0x53bc

Dec 10 2021 19:06:28.886850764 sysevent.fs.zfs.history_event
version = 0x0
class = "sysevent.fs.zfs.history_event"
pool = "tank2"
pool_guid = 0xaec11512e5b5d4a3
pool_state = 0x0
pool_context = 0x0
history_hostname = "nas.root.dom"
history_dsname = "tank2/backup/esxi_nfs"
history_internal_str = "readonly=1"
history_internal_name = "set"
history_dsid = 0xbedc
history_txg = 0x1114574
history_time = 0x61b39724
time = 0x61b39724 0x34dc44cc
eid = 0x53bd

Dec 10 2021 19:06:34.208850151 sysevent.fs.zfs.history_event
version = 0x0
class = "sysevent.fs.zfs.history_event"
pool = "tank2"
pool_guid = 0xaec11512e5b5d4a3
pool_state = 0x0
pool_context = 0x0
history_hostname = "nas.root.dom"
history_dsname = "tank2/backup/esxi_nfs@auto-2021-12-03_18-00"
history_internal_str = " "
history_internal_name = "destroy"
history_dsid = 0x8933
history_txg = 0x1114576
history_time = 0x61b3972a
time = 0x61b3972a 0xc72cce7
eid = 0x53be

Show : zpool history

2021-12-10.19:06:28 zfs recv -s -F -x sharesmb -x sharenfs -x mountpoint tank2/backup/esxi_nfs

Show : zpool history

2021-12-10.19:06:33 zfs set readonly=on tank2/backup/esxi_nfs

 

[Samuel Tai]

The mail actions should be in one of the /var/log/middlewared.log*. However, these might just be a timing issue with a health check, and nothing wrong with your pool. It looks like tank02 is receiving a replication and unavailable for service during the receive. tank02 comes back ONLINE when the replication completes.

 

[websmith]

Weird - I have no mail actions what so ever in the middlewared.log file - the current log file goes from june all the way up until now, and for the 10th of december all there is in there are the hourly update checks.

Found it in the maillog for the 10th where it logs that middlewared is sending mail to me.

Show : mail sent

Dec 10 19:06:39 nas.root.dom 1 2021-12-10T19:06:39.703469+01:00 nas.root.dom middlewared 1786 - - sending mail to xxx@gmail.com
Content-Type: multipart/mixed
MIME-Version: 1.0
Subject: TrueNAS nas.root.dom: Alerts
From: root@nas.root.dom
To: xxx@gmail.com
Date: Fri, 10 Dec 2021 18:06:39 -0000
Message-ID: <truenas-20211210.180639.605823.b'9avh'@nas.root.dom>

Im happy you think this is just a red herring, but something is wrong and needs to be be fixed.

Either the monitoring is not working or rplication is not working, if can take my pool offline during replication.

I am pretty certain that its not a ressource issue, since I am running on a much overpowered machine for the workload: Xeon D-1528 with 128GB RAM - and all it does is receive backups via replication from my main truenas server.

I did not receive any alerts from my ESXi servers that have datasets on that pool mounted during the "outage" - and usually they are very quick to detect errors like this.

Anything else I can do to find out what might be the reason for this scary error?

Do I need to think about replicating data away from the pool?

 

[Alecmascot]

Looking at the Smart Data for the two drives: : there is a disparity between the power related statistics. Would you expect these to be identical or are you happy that they are different ?

9 Power_On_Hours
12 Power_Cycle_Count
192 Power-Off_Retract_Count
193 Load_Cycle_Count

May point to a power issue

 

[websmith]

Looking at the Smart Data for the two drives: : there is a disparity between the power related statistics. Would you expect these to be identical or are you happy that they are different ?

9 Power_On_Hours
12 Power_Cycle_Count
192 Power-Off_Retract_Count
193 Load_Cycle_Count

May point to a power issue

I have no idea if they are expected to be the exact same.

I can see that the numbers almost the same - but to be honest I have no idea if that is because of how the pools have been created in the past - or if they are expected to be exactly the same, considering that the drives should have been running the same amount of time.

I know I have recreated the pool a couple of times in the beginning, so I guess its possible that one drive was spinned down a little more than the other while I was "dicking" around?