System freezes when trying to access encrypted volume

[phenx]

Hi there,

I've been using freenas for some years now and now I've got a problem.. I hope someone might be able to help:

Setup:
Dell PowerEdge T20, Intel Xeon E3-1225 v3 @3.2 GhZ, 20GB RAM, Dell H200 (LSI IT-Mode, FW P17). HDDs: 1x 120GB SSD @Mainboard SATA (FreeNAS VM, some other VMs), 2x 3TB WD Red + 2x 6TB WD Red @H200 (Datastore, even more VMs). UPS: APC Back-UPS 650 passed through to FreeNAS.

The 4 WDD Red drives are encrypted and contain my volume "tank".

Now freenas is runnig 24/7, and I noticed windows could not access the share anymore after month of undisturbed uptime. So I tried to view the web interface ... no response. I remotely logged in (via ESX) and could not even manage a shutdown command to come through. So I killed the VM freenas is running in and rebooted. All fine, web interface coming up again etc. etc. The I switch to "storage" tab, click on my "tank" volume and unlock, enter the passphrase ... message "an error occurred" right next to the freenas logo and "loading" where "tank" had been. System is unresponsive again, can't even be shut down correctly etc.

So reboot again. Short smart test on all 4 devices passes without error. Trying to decrypt -> Crash. I can't even do a "zpool status" or anything on ssh after clicking the unlock button.

I have lot's of important data on these disks, only part of which is regularly backed up and would be realls glad if someone could assist me in getting this running again!

Last output on web interface log before system went unresponsive:

Code:

Jan 14 21:54:28 srv-nas GEOM_ELI: Device gptid/62babe55-3c71-11e5-a510-000c2901ca17.eli created.
Jan 14 21:54:28 srv-nas GEOM_ELI: Encryption: AES-XTS 128
Jan 14 21:54:28 srv-nas GEOM_ELI:	 Crypto: hardware
Jan 14 21:54:30 srv-nas GEOM_ELI: Device gptid/6307fc08-3c71-11e5-a510-000c2901ca17.eli created.
Jan 14 21:54:30 srv-nas GEOM_ELI: Encryption: AES-XTS 128
Jan 14 21:54:30 srv-nas GEOM_ELI:	 Crypto: hardware
Jan 14 21:54:31 srv-nas GEOM_ELI: Device gptid/bb9e8bb4-4833-11e5-b1d8-000c2901ca17.eli created.
Jan 14 21:54:31 srv-nas GEOM_ELI: Encryption: AES-XTS 128
Jan 14 21:54:31 srv-nas GEOM_ELI:	 Crypto: hardware
Jan 14 21:54:33 srv-nas GEOM_ELI: Device gptid/bbed0be3-4833-11e5-b1d8-000c2901ca17.eli created.
Jan 14 21:54:33 srv-nas GEOM_ELI: Encryption: AES-XTS 128
Jan 14 21:54:33 srv-nas GEOM_ELI:	 Crypto: hardware
Jan 14 21:54:34 srv-nas ZFS: vdev state changed, pool_guid=17868101239938344426 vdev_guid=13488614577337946745
Jan 14 21:54:34 srv-nas ZFS: vdev state changed, pool_guid=17868101239938344426 vdev_guid=15366009296938099151
Jan 14 21:54:34 srv-nas ZFS: vdev state changed, pool_guid=17868101239938344426 vdev_guid=4533943380820531032
Jan 14 21:54:34 srv-nas ZFS: vdev state changed, pool_guid=17868101239938344426 vdev_guid=4911396709595730506
Jan 14 21:54:51 srv-nas mountd[1977]: mount request from 10.99.0.2 for non existent path /mnt/tank
Jan 14 21:54:51 srv-nas mountd[1977]: mount request denied from 10.99.0.2 for /mnt/tank

Last output in debug.log:

Code:

Jan 14 21:54:08 srv-nas uwsgi: [middleware.notifier:185] Popen()ing: /sbin/zfs get -r -H -o name,property,value,source -t filesystem,volume compression,compressratio,readonly,org.freenas:description
Jan 14 21:54:27 srv-nas uwsgi: [middleware.notifier:185] Popen()ing: geli attach -j /tmp/tmplict8tmq -k /data/geli/7510e0a2-afb0-4565-acf0-b89e71fc6681.key gptid/62babe55-3c71-11e5-a510-000c2901ca17
Jan 14 21:54:27 srv-nas uwsgi: [middleware.notifier:185] Popen()ing: /sbin/zfs get -r -H -o name,property,value,source -t filesystem,volume compression,compressratio,readonly,org.freenas:description
Jan 14 21:54:28 srv-nas uwsgi: [freeadmin.navtree:114] Unable to import 'freenasUI.api' 'nav': No module named 'freenasUI.api.nav'
Jan 14 21:54:28 srv-nas uwsgi: [freeadmin.navtree:402] App freenasUI.api has no nav.py module, skipping
Jan 14 21:54:28 srv-nas uwsgi: [freeadmin.navtree:114] Unable to import 'freenasUI.freeadmin' 'nav': No module named 'freenasUI.freeadmin.nav'
Jan 14 21:54:28 srv-nas uwsgi: [freeadmin.navtree:402] App freenasUI.freeadmin has no nav.py module, skipping
Jan 14 21:54:28 srv-nas uwsgi: [middleware.notifier:185] Popen()ing: route -nv show default|grep 'interface:'|awk '{ print $2 }'
Jan 14 21:54:28 srv-nas uwsgi: [middleware.notifier:185] Popen()ing: route -nv show -inet6 default|grep 'interface:'|awk '{ print $2 }'
Jan 14 21:54:28 srv-nas uwsgi: [middleware.notifier:185] Popen()ing: route -nv show default|grep 'interface:'|awk '{ print $2 }'
Jan 14 21:54:28 srv-nas uwsgi: [middleware.notifier:185] Popen()ing: route -nv show -inet6 default|grep 'interface:'|awk '{ print $2 }'
Jan 14 21:54:28 srv-nas uwsgi: [middleware.notifier:185] Popen()ing: route -nv show default|grep 'interface:'|awk '{ print $2 }'
Jan 14 21:54:28 srv-nas uwsgi: [middleware.notifier:185] Popen()ing: route -nv show -inet6 default|grep 'interface:'|awk '{ print $2 }'
Jan 14 21:54:28 srv-nas uwsgi: [middleware.notifier:185] Popen()ing: route -nv show default|grep 'interface:'|awk '{ print $2 }'
Jan 14 21:54:28 srv-nas uwsgi: [middleware.notifier:185] Popen()ing: route -nv show -inet6 default|grep 'interface:'|awk '{ print $2 }'
Jan 14 21:54:28 srv-nas uwsgi: [common.warden:406] warden_base.__init__: cmd = list - flags = 0x00000001
Jan 14 21:54:28 srv-nas uwsgi: [common.warden:437] warden_base.__init__: args =  -v
Jan 14 21:54:28 srv-nas uwsgi: [common.warden:443] warden_base.__init__: leave
Jan 14 21:54:28 srv-nas uwsgi: [common.warden:449] warden_base.run: enter
Jan 14 21:54:28 srv-nas uwsgi: [common.warden:458] warden_base.cmd = /usr/local/bin/warden list  -v
Jan 14 21:54:28 srv-nas uwsgi: [common.cmd:189] cmd_pipe.__init__: cmd = /usr/local/bin/warden list  -v, kwargs = {'pipeopen_kwargs': {}}
Jan 14 21:54:28 srv-nas uwsgi: [common.cmd:208] cmd_pipe.__init__: out = Error: No jails found!
Jan 14 21:54:28 srv-nas uwsgi: [common.cmd:219] cmd_pipe.__init__: leave
Jan 14 21:54:28 srv-nas uwsgi: [common.warden:1072] Warden.__call: Failed with '[warden_exception: The command /usr/local/bin/warden list  -v failed: "Error: No jails found!
"]'
Jan 14 21:54:28 srv-nas uwsgi: [middleware.notifier:185] Popen()ing: route -nv show default|grep 'interface:'|awk '{ print $2 }'
Jan 14 21:54:28 srv-nas uwsgi: [middleware.notifier:185] Popen()ing: route -nv show -inet6 default|grep 'interface:'|awk '{ print $2 }'
Jan 14 21:54:28 srv-nas uwsgi: [services.forms:1166] Failed to decrypt DDNS password
Traceback (most recent call last):
  File "./freenasUI/services/models.py", line 1164, in _decrypt_password
	self.ddns_password = notifier().pwenc_decrypt(self.ddns_password)
  File "./freenasUI/middleware/notifier.py", line 3859, in pwenc_decrypt
	encrypted = base64.b64decode(encrypted)
  File "/usr/local/lib/python3.6/base64.py", line 87, in b64decode
	return binascii.a2b_base64(s)
binascii.Error: Incorrect padding
Jan 14 21:54:28 srv-nas uwsgi: [freeadmin.navtree:114] Unable to import 'freenasUI.support' 'nav': No module named 'freenasUI.support.nav'
Jan 14 21:54:28 srv-nas uwsgi: [freeadmin.navtree:402] App freenasUI.support has no nav.py module, skipping
Jan 14 21:54:28 srv-nas uwsgi: [freeadmin.navtree:114] Unable to import 'freenasUI.documentation' 'nav': No module named 'freenasUI.documentation.nav'
Jan 14 21:54:28 srv-nas uwsgi: [freeadmin.navtree:402] App freenasUI.documentation has no nav.py module, skipping
Jan 14 21:54:28 srv-nas uwsgi: [common.warden:406] warden_base.__init__: cmd = list - flags = 0x00000001
Jan 14 21:54:28 srv-nas uwsgi: [common.warden:437] warden_base.__init__: args =  -v
Jan 14 21:54:28 srv-nas uwsgi: [common.warden:443] warden_base.__init__: leave
Jan 14 21:54:28 srv-nas uwsgi: [common.warden:449] warden_base.run: enter
Jan 14 21:54:28 srv-nas uwsgi: [common.warden:458] warden_base.cmd = /usr/local/bin/warden list  -v
Jan 14 21:54:28 srv-nas uwsgi: [common.cmd:189] cmd_pipe.__init__: cmd = /usr/local/bin/warden list  -v, kwargs = {'pipeopen_kwargs': {}}
Jan 14 21:54:28 srv-nas uwsgi: [common.cmd:208] cmd_pipe.__init__: out = Error: No jails found!
Jan 14 21:54:28 srv-nas uwsgi: [common.cmd:219] cmd_pipe.__init__: leave
Jan 14 21:54:28 srv-nas uwsgi: [common.warden:1072] Warden.__call: Failed with '[warden_exception: The command /usr/local/bin/warden list  -v failed: "Error: No jails found!
"]'
Jan 14 21:54:28 srv-nas uwsgi: [middleware.notifier:194] geli attach -j /tmp/tmplict8tmq -k /data/geli/7510e0a2-afb0-4565-acf0-b89e71fc6681.key gptid/62babe55-3c71-11e5-a510-000c2901ca17 -> 0
Jan 14 21:54:28 srv-nas uwsgi: [middleware.notifier:185] Popen()ing: geli attach -j /tmp/tmplict8tmq -k /data/geli/7510e0a2-afb0-4565-acf0-b89e71fc6681.key gptid/6307fc08-3c71-11e5-a510-000c2901ca17
Jan 14 21:54:30 srv-nas uwsgi: [middleware.notifier:194] geli attach -j /tmp/tmplict8tmq -k /data/geli/7510e0a2-afb0-4565-acf0-b89e71fc6681.key gptid/6307fc08-3c71-11e5-a510-000c2901ca17 -> 0
Jan 14 21:54:30 srv-nas uwsgi: [middleware.notifier:185] Popen()ing: geli attach -j /tmp/tmplict8tmq -k /data/geli/7510e0a2-afb0-4565-acf0-b89e71fc6681.key gptid/bb9e8bb4-4833-11e5-b1d8-000c2901ca17
Jan 14 21:54:31 srv-nas uwsgi: [middleware.notifier:194] geli attach -j /tmp/tmplict8tmq -k /data/geli/7510e0a2-afb0-4565-acf0-b89e71fc6681.key gptid/bb9e8bb4-4833-11e5-b1d8-000c2901ca17 -> 0
Jan 14 21:54:31 srv-nas uwsgi: [middleware.notifier:185] Popen()ing: geli attach -j /tmp/tmplict8tmq -k /data/geli/7510e0a2-afb0-4565-acf0-b89e71fc6681.key gptid/bbed0be3-4833-11e5-b1d8-000c2901ca17
Jan 14 21:54:33 srv-nas uwsgi: [middleware.notifier:194] geli attach -j /tmp/tmplict8tmq -k /data/geli/7510e0a2-afb0-4565-acf0-b89e71fc6681.key gptid/bbed0be3-4833-11e5-b1d8-000c2901ca17 -> 0
Jan 14 21:54:33 srv-nas uwsgi: [middleware.notifier:185] Popen()ing: zpool import -f -R /mnt 17868101239938344426
Jan 14 21:55:28 srv-nas uwsgi: [middleware.notifier:185] Popen()ing: /sbin/zfs get -r -H -o name,property,value,source -t filesystem,volume compression,compressratio,readonly,org.freenas:description

Is there any additional info I can provide? freenas-debug -A -e email@address.com does not work after trying to mount because somewhere in between the system crashed when it tries to collect debug info regarding the disks.. so I attached a copy before trying to mount.

 

[Ericloewe]

For future reference: The debug tarball says this is FreeNAS 11.1

Opening the decrypted disks seems to work normally, which suggests this is ZFS crashing.

You'll probably want to file a bug report to have the devs take a look at this. Include your debug tarball.

 

[phenx]

Thank's for the quick analysis.. passed it on to the developers / bug tracking system here: https://redmine.ixsystems.com/issues/27798

 

[phenx]

For future reference: It was a bug fixed in FreeNAS 11.1-U1 released a few days after I saw the issue. Scrubbing sometimes (including my case) never finished and caused high CPU usage. After the update, it finished within 5hrs which is normal for my system and everything's fine again!