FreeNAS 9.10.1-U3 and U4 crash while unlocking encrypted volume

[alykalanany]

The reason I post here and not on the bugtracker is I have never posted an issue there before and all the categories and options confuse me.

Anyway. I've been running FreeNAS-9.10.1-U2 without problems.

I gave U3 a go when it popped up in the notifications (9.10 STABLE train) but the server just stopped responding when I tried unlocking my encrypted volume. I didn't have time to investigate at the time so I went back to U2.

Now that U4 was released I thought I'd give it a go again.. Same problem! But now I just had to investigate a bit.. And it seems it just reboots without any messages back to BIOS POST. I recorded the console screen via the servers BMC interface for both U2 and U4 to see the differences.

What you can't see in the videos is what I do in the GUI, which login, go to Storage tab and click unlock key, and put in passphrase and select to restart services CIFS and Jails/Plugins, then press OK.

FreeNAS-9.10.1-U2 (works)
FreeNAS-9.10.1-U4 (crash/reboot)

What do you guys think? Is this a bug or something missconfigured that appears only now after some unrelated changes in the release build?


Machine configuration:
AsRock C2550D4I motherboard
Intel Atom CPU C2550 QC 2.4-2.6 GHz
Crucial 16 GB ECC RAM
Boot drives: 2 x ADATA SP600 m.2 2242 128 GB on a PCIe Host adapter card
Data drives: 6 x HGST NAS SATA 3 TB
Data drives are configured in a single raidz2 volume, geli encrypted.

 

[dlavigne]

Were you able to figure this out?

 

[alykalanany]

No, but I haven't had time to investigate further because I'm moving to a new apartment. Are there any logs that I could collect that could help?

 

[dlavigne]

Is there anything related in /var/log/messages?

 

[alykalanany]

This is a snippet from the messages log from the date of the original post. I can see nothing between the regular "link state changed" messages and the first messages of the next boot:

Show

Booting up U4

Code:

Nov 17 19:45:56 freenas syslog-ng[1516]: syslog-ng starting up; version='3.6.4'
Nov 17 19:45:56 freenas Table 'FACP' at 0x7edea258
Nov 17 19:45:56 freenas Table 'FPDT' at 0x7edea368
Nov 17 19:45:56 freenas Table 'FIDT' at 0x7edea3b0
Nov 17 19:45:56 freenas Table 'HPET' at 0x7edea450
Nov 17 19:45:56 freenas Table 'AAFT' at 0x7edea488
Nov 17 19:45:56 freenas Table 'SPMI' at 0x7edea4b8
Nov 17 19:45:56 freenas Table 'MCFG' at 0x7edea4f8
Nov 17 19:45:56 freenas Table 'WDAT' at 0x7edea538
Nov 17 19:45:56 freenas Table 'UEFI' at 0x7edea6e8
Nov 17 19:45:56 freenas Table 'APIC' at 0x7edea730
Nov 17 19:45:56 freenas APIC: Found table at 0x7edea730
Nov 17 19:45:56 freenas APIC: Using the MADT enumerator.
Nov 17 19:45:56 freenas MADT: Found CPU APIC ID 0 ACPI ID 1: enabled
Nov 17 19:45:56 freenas SMP: Added CPU 0 (AP)
Nov 17 19:45:56 freenas MADT: Found CPU APIC ID 2 ACPI ID 2: enabled
Nov 17 19:45:56 freenas SMP: Added CPU 2 (AP)
Nov 17 19:45:56 freenas MADT: Found CPU APIC ID 4 ACPI ID 3: enabled
Nov 17 19:45:56 freenas SMP: Added CPU 4 (AP)
Nov 17 19:45:56 freenas MADT: Found CPU APIC ID 6 ACPI ID 4: enabled
Nov 17 19:45:56 freenas SMP: Added CPU 6 (AP)
Nov 17 19:45:56 freenas Copyright (c) 1992-2016 The FreeBSD Project.
Nov 17 19:45:56 freenas Copyright (c) 1979, 1980, 1983, 1986, 1988, 1989, 1991, 1992, 1993, 1994
Nov 17 19:45:56 freenas 	The Regents of the University of California. All rights reserved.
Nov 17 19:45:56 freenas FreeBSD is a registered trademark of The FreeBSD Foundation.
Nov 17 19:45:56 freenas FreeBSD 10.3-STABLE #0 r295946+07c41cd(9.10-STABLE): Wed Nov  9 00:19:25 UTC 2016
Nov 17 19:45:56 freenas root@gauntlet:/freenas-9.10-releng/_BE/objs/freenas-9.10-releng/_BE/os/sys/FreeNAS.amd64 amd64
Nov 17 19:45:56 freenas FreeBSD clang version 3.4.1 (tags/RELEASE_34/dot1-final 208032) 20140512
Nov 17 19:45:56 freenas Preloaded elf64 kernel "/boot/kernel/kernel" at 0xffffffff81e3158c.
Nov 17 19:45:56 freenas Preloaded /boot/zfs/zpool.cache "/boot/zfs/zpool.cache" at 0xffffffff81e317ec.
Nov 17 19:45:56 freenas Preloaded elf obj module "/boot/kernel/ispfw.ko" at 0xffffffff81e3184c.
Nov 17 19:45:56 freenas Calibrating TSC clock ... TSC clock: 2400058296 Hz
Nov 17 19:45:56 freenas CPU: Intel(R) Atom(TM) CPU  C2550  @ 2.40GHz (2400.06-MHz K8-class CPU)

Skipping lots of bootup messages..

Code:

Nov 17 19:46:00 freenas GEOM_ELI: Device ada4p1.eli created.
Nov 17 19:46:00 freenas GEOM_ELI: Encryption: AES-XTS 128
Nov 17 19:46:00 freenas GEOM_ELI:  Crypto: hardware
Nov 17 19:46:00 freenas GEOM_ELI: Device ada7p1.eli created.
Nov 17 19:46:00 freenas GEOM_ELI: Encryption: AES-XTS 128
Nov 17 19:46:00 freenas GEOM_ELI:  Crypto: hardware
Nov 17 19:46:00 freenas GEOM_ELI: Device ada2p1.eli created.
Nov 17 19:46:00 freenas GEOM_ELI: Encryption: AES-XTS 128
Nov 17 19:46:00 freenas GEOM_ELI:  Crypto: hardware
Nov 17 19:46:00 freenas GEOM_ELI: Device ada3p1.eli created.
Nov 17 19:46:00 freenas GEOM_ELI: Encryption: AES-XTS 128
Nov 17 19:46:00 freenas GEOM_ELI:  Crypto: hardware
Nov 17 19:46:00 freenas GEOM_ELI: Device ada5p1.eli created.
Nov 17 19:46:00 freenas GEOM_ELI: Encryption: AES-XTS 128
Nov 17 19:46:00 freenas GEOM_ELI:  Crypto: hardware
Nov 17 19:46:00 freenas GEOM_ELI: Device ada6p1.eli created.
Nov 17 19:46:00 freenas GEOM_ELI: Encryption: AES-XTS 128
Nov 17 19:46:00 freenas GEOM_ELI:  Crypto: hardware
Nov 17 19:46:01 freenas linprocfs registered
Nov 17 19:46:01 freenas ntpd[2013]: ntpd 4.2.8p8-a (1): Starting
Nov 17 19:46:08 freenas generate_smb4_conf.py: [generate_smb4_conf:1498] Unable to open /var/db/samba4/private/secrets.tdb: [Errno 2] No such file or directory
Nov 17 19:46:08 freenas generate_smb4_conf.py: [common.pipesubr:66] Popen()ing: /sbin/sysctl -n 'kern.maxfilesperproc'
Nov 17 19:46:08 freenas generate_smb4_conf.py: [common.pipesubr:66] Popen()ing: /usr/local/bin/net -d 0 getlocalsid
Nov 17 19:46:09 freenas smbd: dnssd_clientstub ConnectToServer: connect()-> No of tries: 1
Nov 17 19:46:10 freenas smbd: dnssd_clientstub ConnectToServer: connect()-> No of tries: 2
Nov 17 19:46:11 freenas root: /etc/rc: WARNING: failed precmd routine for vmware_guestd
Nov 17 19:46:11 freenas smbd: dnssd_clientstub ConnectToServer: connect()-> No of tries: 3
Nov 17 19:46:12 freenas smbd: dnssd_clientstub ConnectToServer: connect() failed path:/var/run/mdnsd Socket:35 Err:-1 Errno:2 No such file or directory
Nov 17 19:46:54 freenas login: ROOT LOGIN (root) ON ttyv0
Nov 17 19:46:55 freenas syslog-ng[4077]: syslog-ng starting up; version='3.6.4'
Nov 17 19:46:55 freenas kernel: pid 1516 (syslog-ng), uid 0: exited on signal 6 (core dumped)
Nov 17 19:47:30 freenas GEOM_ELI: Device gptid/20b899ab-ec52-11e5-a821-6805ca278486.eli created.
Nov 17 19:47:30 freenas GEOM_ELI: Encryption: AES-XTS 128
Nov 17 19:47:30 freenas GEOM_ELI:  Crypto: hardware
Nov 17 19:47:32 freenas GEOM_ELI: Device gptid/21b6aa1a-ec52-11e5-a821-6805ca278486.eli created.
Nov 17 19:47:32 freenas GEOM_ELI: Encryption: AES-XTS 128
Nov 17 19:47:32 freenas GEOM_ELI:  Crypto: hardware
Nov 17 19:47:34 freenas GEOM_ELI: Device gptid/22b7a258-ec52-11e5-a821-6805ca278486.eli created.
Nov 17 19:47:34 freenas GEOM_ELI: Encryption: AES-XTS 128
Nov 17 19:47:34 freenas GEOM_ELI:  Crypto: hardware
Nov 17 19:47:36 freenas GEOM_ELI: Device gptid/23afd69c-ec52-11e5-a821-6805ca278486.eli created.
Nov 17 19:47:36 freenas GEOM_ELI: Encryption: AES-XTS 128
Nov 17 19:47:36 freenas GEOM_ELI:  Crypto: hardware
Nov 17 19:47:38 freenas GEOM_ELI: Device gptid/24ae451b-ec52-11e5-a821-6805ca278486.eli created.
Nov 17 19:47:38 freenas GEOM_ELI: Encryption: AES-XTS 128
Nov 17 19:47:38 freenas GEOM_ELI:  Crypto: hardware
Nov 17 19:47:40 freenas GEOM_ELI: Device gptid/2599bd3c-ec52-11e5-a821-6805ca278486.eli created.
Nov 17 19:47:40 freenas GEOM_ELI: Encryption: AES-XTS 128
Nov 17 19:47:40 freenas GEOM_ELI:  Crypto: hardware
Nov 17 19:47:40 freenas ZFS: vdev state changed, pool_guid=4386113549054365781 vdev_guid=2982785225329187192
Nov 17 19:47:40 freenas ZFS: vdev state changed, pool_guid=4386113549054365781 vdev_guid=12223760423562232827
Nov 17 19:47:40 freenas ZFS: vdev state changed, pool_guid=4386113549054365781 vdev_guid=4968430088591128216
Nov 17 19:47:40 freenas ZFS: vdev state changed, pool_guid=4386113549054365781 vdev_guid=7486200010901125530
Nov 17 19:47:40 freenas ZFS: vdev state changed, pool_guid=4386113549054365781 vdev_guid=4095048244165284097
Nov 17 19:47:40 freenas ZFS: vdev state changed, pool_guid=4386113549054365781 vdev_guid=10274110800196606011
Nov 17 19:48:23 freenas generate_smb4_conf.py: [common.pipesubr:66] Popen()ing: /sbin/sysctl -n 'kern.maxfilesperproc'
Nov 17 19:48:23 freenas generate_smb4_conf.py: [common.pipesubr:66] Popen()ing: mount
Nov 17 19:48:23 freenas generate_smb4_conf.py: [common.pipesubr:66] Popen()ing: mount
Nov 17 19:48:23 freenas generate_smb4_conf.py: [common.pipesubr:66] Popen()ing: /usr/local/bin/net -d 0 getlocalsid
Nov 17 19:48:23 freenas notifier: Stopping winbindd.
Nov 17 19:48:23 freenas notifier: Waiting for PIDS: 2310.
Nov 17 19:48:23 freenas notifier: Stopping smbd.
Nov 17 19:48:23 freenas notifier: Waiting for PIDS: 2306.
Nov 17 19:48:23 freenas notifier: Stopping nmbd.
Nov 17 19:48:23 freenas notifier: Waiting for PIDS: 2303.
Nov 17 19:48:24 freenas notifier: Performing sanity check on Samba configuration: OK
Nov 17 19:48:24 freenas notifier: winbindd not running? (check /var/run/samba/winbindd.pid).
Nov 17 19:48:24 freenas notifier: smbd not running? (check /var/run/samba/smbd.pid).
Nov 17 19:48:24 freenas notifier: nmbd not running? (check /var/run/samba/nmbd.pid).
Nov 17 19:48:24 freenas notifier: Performing sanity check on Samba configuration: OK
Nov 17 19:48:24 freenas notifier: Starting nmbd.
Nov 17 19:48:24 freenas notifier: Starting smbd.
Nov 17 19:48:24 freenas notifier: Starting winbindd.
Nov 17 19:48:24 freenas notifier: Stopping mdnsd.
Nov 17 19:48:24 freenas smbd: dnssd_clientstub DNSServiceProcessResult called with DNSServiceRef with no ProcessReply function
Nov 17 19:48:24 freenas notifier: Waiting for PIDS: 3049.
Nov 17 19:48:24 freenas notifier: Starting mdnsd.
Nov 17 19:48:27 freenas bridge0: bpf attached
Nov 17 19:48:27 freenas bridge0: Ethernet address: 02:5d:bf:c3:1c:00
Nov 17 19:48:27 freenas kernel: igb0: promiscuous mode enabled
Nov 17 19:48:27 freenas kernel: bridge0: link state changed to UP
Nov 17 19:48:27 freenas kernel: bridge0: link state changed to UP
Nov 17 19:48:27 freenas epair0a: bpf attached
Nov 17 19:48:27 freenas epair0a: Ethernet address: 02:ff:60:00:05:0a
Nov 17 19:48:27 freenas epair0b: bpf attached
Nov 17 19:48:27 freenas epair0b: Ethernet address: 02:ff:b0:00:06:0b
Nov 17 19:48:27 freenas kernel: epair0a: link state changed to UP
Nov 17 19:48:27 freenas kernel: epair0a: link state changed to UP
Nov 17 19:48:27 freenas kernel: epair0b: link state changed to UP
Nov 17 19:48:27 freenas kernel: epair0b: link state changed to UP
Nov 17 19:48:27 freenas igb0: Link is Down
Nov 17 19:48:27 freenas kernel: igb0: link state changed to DOWN
Nov 17 19:48:27 freenas kernel: igb0: link state changed to DOWN
Nov 17 19:48:27 freenas kernel: epair0a: promiscuous mode enabled
Nov 17 19:48:27 freenas kernel: ng_ether_ifnet_arrival_event: can't re-name node epair0b
Nov 17 19:48:27 freenas kernel: ng_ether_ifnet_arrival_event: can't re-name node epair0b
Nov 17 19:48:30 freenas igb0: Link is up 1000 Mbps Full Duplex, Flow Control: Full
Nov 17 19:48:31 freenas kernel: igb0: link state changed to UP
Nov 17 19:48:31 freenas kernel: igb0: link state changed to UP
Nov 17 19:48:39 freenas epair1a: bpf attached
Nov 17 19:48:39 freenas epair1a: Ethernet address: 02:ff:60:00:06:0a
Nov 17 19:48:39 freenas epair1b: bpf attached
Nov 17 19:48:39 freenas epair1b: Ethernet address: 02:ff:b0:00:07:0b
Nov 17 19:48:39 freenas kernel: epair1a: link state changed to UP
Nov 17 19:48:39 freenas kernel: epair1a: link state changed to UP
Nov 17 19:48:39 freenas kernel: epair1b: link state changed to UP
Nov 17 19:48:39 freenas kernel: epair1b: link state changed to UP
Nov 17 19:48:39 freenas kernel: epair1a: promiscuous mode enabled
Nov 17 19:48:40 freenas kernel: ng_ether_ifnet_arrival_event: can't re-name node epair1b
Nov 17 19:48:40 freenas kernel: ng_ether_ifnet_arrival_event: can't re-name node epair1b
Nov 17 19:48:52 freenas epair2a: bpf attached
Nov 17 19:48:52 freenas epair2a: Ethernet address: 02:ff:60:00:07:0a
Nov 17 19:48:52 freenas epair2b: bpf attached
Nov 17 19:48:52 freenas epair2b: Ethernet address: 02:ff:b0:00:08:0b
Nov 17 19:48:52 freenas kernel: epair2a: link state changed to UP
Nov 17 19:48:52 freenas kernel: epair2a: link state changed to UP
Nov 17 19:48:52 freenas kernel: epair2b: link state changed to UP
Nov 17 19:48:52 freenas kernel: epair2b: link state changed to UP
Nov 17 19:48:52 freenas kernel: epair2a: promiscuous mode enabled
Nov 17 19:48:52 freenas kernel: ng_ether_ifnet_arrival_event: can't re-name node epair2b
Nov 17 19:48:52 freenas kernel: ng_ether_ifnet_arrival_event: can't re-name node epair2b
Nov 17 19:51:05 freenas syslog-ng[1513]: syslog-ng starting up; version='3.6.4'
Nov 17 19:51:05 freenas Copyright (c) 1992-2016 The FreeBSD Project.
Nov 17 19:51:05 freenas Copyright (c) 1979, 1980, 1983, 1986, 1988, 1989, 1991, 1992, 1993, 1994
Nov 17 19:51:05 freenas	The Regents of the University of California. All rights reserved.
Nov 17 19:51:05 freenas FreeBSD is a registered trademark of The FreeBSD Foundation.
Nov 17 19:51:05 freenas FreeBSD 10.3-STABLE #0 r295946+0ea9076(9.10-STABLE): Mon Oct  3 06:51:23 UTC 2016
Nov 17 19:51:05 freenas root@gauntlet:/freenas-9.10-releng/_BE/objs/freenas-9.10-releng/_BE/os/sys/FreeNAS.amd64 amd64
Nov 17 19:51:05 freenas FreeBSD clang version 3.4.1 (tags/RELEASE_34/dot1-final 208032) 20140512
Nov 17 19:51:05 freenas CPU: Intel(R) Atom(TM) CPU  C2550  @ 2.40GHz (2400.07-MHz K8-class CPU)

Booted again to U2..

I didn't post the complete log, as I'm not sure if it contains private information. If you think it is safe to post, I will. Or if you know a better method to share it..

 

[dlavigne]

Did you ever resolve this? If not, it is worthwhile to create a bug report at bugs.freenas.org so a developer can review the logs. If you do, post the issue number here.

 

[alykalanany]

I just got a couple minutes over and decided to try 9.10.2-U1 and same thing happens :/ Guess I'm stuck att 9.10.1-U2 for now :)

 

[dlavigne]

Still worth creating a bug report. Note that when you include your debug in the report, it will be marked as private so only you and the dev will see it. Once the cause is determined, they will delete the debug and mark the ticket public so others can see the fix.

 

[alykalanany]

OK, I will do that when I have some time over, possibly the following weekend. Thanks for the instructions!

 

[alykalanany]

So, I didn't get around to creating a bug report, but I think I've finally found the solution here: ASRock Rack C2750D4I BMC / Watchdog Issue

It doesn't exactly describe my issue, but I have the ASRock Rack C2550D4I which is the same board, just fewer cores in the CPU, so I gave the new BMC firmware a try! (version 00.30.00, released 2/15/2017)

It seems the new BMC firmware solved this issue as well! I'm now running FreeNAS-9.10.2-U3 (updated through freenas GUI) and it has been running for an hour now without problems.