blueberryjr
Dabbler
- Joined
- Sep 7, 2017
- Messages
- 15
Running Ryzen 2920x, 64gb memory, 8x 8TB WD white drives, intel optaine drive as boot, FreeNAS-11.2-U5 (Build Date: Jun 24, 2019 18:41)
I've done some searching and it seems like a lot of people have been running into not being able to gracefully shutdown freenas over the years. I've taken a look at those and it seems none have had the correct solution for me. Any help here is appreciated!
Restart command works fine.
So main issue: Shutdown command does not work, will freeze a bit after "Terminated" displays on console, after terminated is displayed the console says something about shutting down the network interfaces then prettymuch always gets stuck on detaching the swap?
Log from daemon.log from boot to shutdown command
From that log I thought there was something wrong with middleware(Not sure what that is). Found these errors in that log during the shutdown times:
I've done some searching and it seems like a lot of people have been running into not being able to gracefully shutdown freenas over the years. I've taken a look at those and it seems none have had the correct solution for me. Any help here is appreciated!
Restart command works fine.
So main issue: Shutdown command does not work, will freeze a bit after "Terminated" displays on console, after terminated is displayed the console says something about shutting down the network interfaces then prettymuch always gets stuck on detaching the swap?
Log from daemon.log from boot to shutdown command
Code:
Sep 14 18:39:54 freenas.local usbhid-ups[3387]: Startup successful Sep 14 18:39:54 freenas.local upsd[3388]: listening on 127.0.0.1 port 3493 Sep 14 18:39:54 freenas.local upsd[3388]: Connected to UPS [ups]: usbhid-ups-ups Sep 14 18:39:54 freenas.local upsd[3388]: /usr/local/etc/nut/cmdvartab not found - disabling descriptions Sep 14 18:39:54 freenas.local upsd[3389]: Startup successful Sep 14 18:39:54 freenas.local upslog[3392]: Startup successful Sep 14 18:39:54 freenas.local upsmon[3395]: Startup successful Sep 14 18:39:54 freenas.local upsd[3389]: User upsmon@127.0.0.1 logged into UPS [ups] Sep 14 18:39:55 freenas.local usbhid-ups[3387]: libusb_get_interrupt: Unknown error Sep 14 18:39:55 freenas.local smartd[3485]: smartd 6.6 2017-11-05 r4594 [FreeBSD 11.2-STABLE amd64] (local build) Sep 14 18:39:55 freenas.local smartd[3485]: Copyright (C) 2002-17, Bruce Allen, Christian Franke, www.smartmontools.org Sep 14 18:39:55 freenas.local smartd[3485]: Opened configuration file /usr/local/etc/smartd.conf Sep 14 18:39:55 freenas.local smartd[3485]: Drive: /dev/ada7, implied '-a' Directive on line 1 of file /usr/local/etc/smartd.conf Sep 14 18:39:55 freenas.local smartd[3485]: Drive: /dev/ada6, implied '-a' Directive on line 2 of file /usr/local/etc/smartd.conf Sep 14 18:39:55 freenas.local smartd[3485]: Drive: /dev/ada5, implied '-a' Directive on line 3 of file /usr/local/etc/smartd.conf Sep 14 18:39:55 freenas.local smartd[3485]: Drive: /dev/ada4, implied '-a' Directive on line 4 of file /usr/local/etc/smartd.conf Sep 14 18:39:55 freenas.local smartd[3485]: Drive: /dev/ada3, implied '-a' Directive on line 5 of file /usr/local/etc/smartd.conf Sep 14 18:39:55 freenas.local smartd[3485]: Drive: /dev/ada2, implied '-a' Directive on line 6 of file /usr/local/etc/smartd.conf Sep 14 18:39:55 freenas.local smartd[3485]: Drive: /dev/ada1, implied '-a' Directive on line 7 of file /usr/local/etc/smartd.conf Sep 14 18:39:55 freenas.local smartd[3485]: Drive: /dev/ada0, implied '-a' Directive on line 8 of file /usr/local/etc/smartd.conf Sep 14 18:39:55 freenas.local smartd[3485]: Configuration file /usr/local/etc/smartd.conf parsed. Sep 14 18:39:55 freenas.local smartd[3485]: Device: /dev/ada7, opened Sep 14 18:39:55 freenas.local smartd[3485]: Device: /dev/ada7, WDC WD80EMAZ-00WJTA0, S/N:2SG2T5YJ, WWN:5-000cca-27dc1438e, FW:83.H0A83, 8.00 TB Sep 14 18:39:55 freenas.local smartd[3485]: Device: /dev/ada7, not found in smartd database. Sep 14 18:39:55 freenas.local smartd[3485]: Device: /dev/ada7, is SMART capable. Adding to "monitor" list. Sep 14 18:39:55 freenas.local smartd[3485]: Device: /dev/ada6, opened Sep 14 18:39:55 freenas.local smartd[3485]: Device: /dev/ada6, WDC WD80EMAZ-00WJTA0, S/N:2SG34DHW, WWN:5-000cca-27dc16da4, FW:83.H0A83, 8.00 TB Sep 14 18:39:55 freenas.local smartd[3485]: Device: /dev/ada6, not found in smartd database. Sep 14 18:39:55 freenas.local smartd[3485]: Device: /dev/ada6, is SMART capable. Adding to "monitor" list. Sep 14 18:39:55 freenas.local smartd[3485]: Device: /dev/ada5, opened Sep 14 18:39:55 freenas.local smartd[3485]: Device: /dev/ada5, WDC WD80EMAZ-00WJTA0, S/N:2SG3DALJ, WWN:5-000cca-27dc18b71, FW:83.H0A83, 8.00 TB Sep 14 18:39:55 freenas.local smartd[3485]: Device: /dev/ada5, not found in smartd database. Sep 14 18:39:55 freenas.local smartd[3485]: Device: /dev/ada5, is SMART capable. Adding to "monitor" list. Sep 14 18:39:55 freenas.local smartd[3485]: Device: /dev/ada4, opened Sep 14 18:39:55 freenas.local smartd[3485]: Device: /dev/ada4, WDC WD80EZAZ-11TDBA0, S/N:JEK6J6PN, WWN:5-000cca-267ed3d9c, FW:83.H0A83, 8.00 TB Sep 14 18:39:55 freenas.local smartd[3485]: Device: /dev/ada4, not found in smartd database. Sep 14 18:39:55 freenas.local smartd[3485]: Device: /dev/ada4, is SMART capable. Adding to "monitor" list. Sep 14 18:39:55 freenas.local smartd[3485]: Device: /dev/ada3, opened Sep 14 18:39:55 freenas.local smartd[3485]: Device: /dev/ada3, WDC WD80EZAZ-11TDBA0, S/N:7HKSZ6PJ, WWN:5-000cca-257f52c79, FW:83.H0A83, 8.00 TB Sep 14 18:39:55 freenas.local smartd[3485]: Device: /dev/ada3, not found in smartd database. Sep 14 18:39:55 freenas.local smartd[3485]: Device: /dev/ada3, is SMART capable. Adding to "monitor" list. Sep 14 18:39:55 freenas.local smartd[3485]: Device: /dev/ada2, opened Sep 14 18:39:55 freenas.local smartd[3485]: Device: /dev/ada2, WDC WD80EZAZ-11TDBA0, S/N:7HKT55MH, WWN:5-000cca-257f542de, FW:83.H0A83, 8.00 TB Sep 14 18:39:55 freenas.local smartd[3485]: Device: /dev/ada2, not found in smartd database. Sep 14 18:39:55 freenas.local smartd[3485]: Device: /dev/ada2, is SMART capable. Adding to "monitor" list. Sep 14 18:39:55 freenas.local smartd[3485]: Device: /dev/ada1, opened Sep 14 18:39:55 freenas.local smartd[3485]: Device: /dev/ada1, WDC WD80EZAZ-11TDBA0, S/N:JEK869SN, WWN:5-000cca-267ee012f, FW:83.H0A83, 8.00 TB Sep 14 18:39:55 freenas.local smartd[3485]: Device: /dev/ada1, not found in smartd database. Sep 14 18:39:55 freenas.local smartd[3485]: Device: /dev/ada1, is SMART capable. Adding to "monitor" list. Sep 14 18:39:55 freenas.local smartd[3485]: Device: /dev/ada0, opened Sep 14 18:39:55 freenas.local smartd[3485]: Device: /dev/ada0, WDC WD80EMAZ-00WJTA0, S/N:2SG2T0UJ, WWN:5-000cca-27dc142ef, FW:83.H0A83, 8.00 TB Sep 14 18:39:55 freenas.local smartd[3485]: Device: /dev/ada0, not found in smartd database. Sep 14 18:39:55 freenas.local smartd[3485]: Device: /dev/ada0, is SMART capable. Adding to "monitor" list. Sep 14 18:39:55 freenas.local smartd[3485]: Monitoring 8 ATA/SATA, 0 SCSI/SAS and 0 NVMe devices Sep 14 18:39:55 freenas.local mDNSResponder: mDNSResponder (Engineering Build) (Jun 24 2019 17:32:30) starting Sep 14 18:39:55 freenas.local mDNSResponder: mDNS_AddDNSServer: Lock not held! mDNS_busy (0) mDNS_reentrancy (0) Sep 14 18:39:55 freenas.local mDNSResponder: mDNS_AddDNSServer: Lock not held! mDNS_busy (0) mDNS_reentrancy (0) Sep 14 18:39:56 freenas.local smartd[3485]: file /var/run/smartd-daemon.pid written containing PID 3485 Sep 14 18:39:57 freenas.local usbhid-ups[3387]: libusb_get_interrupt: Unknown error Sep 14 18:39:57 freenas.local collectd[4027]: plugin_load: plugin "syslog" successfully loaded. Sep 14 18:39:57 freenas.local collectd[4027]: plugin_load: plugin "threshold" successfully loaded. Sep 14 18:39:57 freenas.local collectd[4027]: plugin_load: plugin "zfs_arc" successfully loaded. Sep 14 18:39:57 freenas.local collectd[4027]: plugin_load: plugin "zfs_arc_v2" successfully loaded. Sep 14 18:39:57 freenas.local collectd[4027]: type = syslog, key = LogLevel, value = err Sep 14 18:39:57 freenas.local zfsd: ConnectToDevd: Connecting to devd. Sep 14 18:39:57 freenas.local zfsd: Connection to devd successful Sep 14 18:39:59 freenas.local usbhid-ups[3387]: libusb_get_interrupt: Unknown error Sep 14 18:40:01 freenas.local zfsd: Disconnecting from devd. Sep 14 18:40:02 freenas.local mDNSResponder: mDNSResponder (Engineering Build) (Jun 24 2019 17:32:30) stopping Sep 14 18:40:03 freenas.local usbhid-ups[3387]: libusb_get_interrupt: Unknown error Sep 14 18:40:03 freenas.local smartd[3485]: smartd received signal 15: Terminated Sep 14 18:40:03 freenas.local smartd[3485]: smartd is exiting (exit status 0) Sep 14 18:40:03 freenas.local upsmon[3396]: Signal 15: exiting Sep 14 18:40:03 freenas.local upsd[3389]: User upsmon@127.0.0.1 logged out from UPS [ups] Sep 14 18:40:03 freenas.local upsmon[3395]: upsmon parent: read Sep 14 18:40:03 freenas.local upslog[3392]: Signal 15: exiting Sep 14 18:40:03 freenas.local upsd[3389]: mainloop: Interrupted system call Sep 14 18:40:03 freenas.local upsd[3389]: Signal 15: exiting Sep 14 18:40:03 freenas.local usbhid-ups[3387]: Signal 15: exiting Sep 14 18:40:05 freenas.local mDNSResponder: mDNSResponder (Engineering Build) (Jun 24 2019 17:32:30) stopping Sep 14 18:40:05 freenas.local mDNSResponder: mDNS_FinalExit failed to send goodbye for: 0000000801089580 01 25 _ssh._tcp.local. PTR freenas._ssh._tcp.local. Sep 14 18:40:05 freenas.local mDNSResponder: mDNS_FinalExit failed to send goodbye for: 000000080108A980 01 30 _sftp-ssh._tcp.local. PTR freenas._sftp-ssh._tcp.local. Sep 14 18:40:05 freenas.local mDNSResponder: mDNS_FinalExit failed to send goodbye for: 000000080108BD80 01 26 _http._tcp.local. PTR freenas._http._tcp.local. Sep 14 18:40:05 freenas.local mDNSResponder: mDNS_FinalExit failed to send goodbye for: 000000080108D180 01 32 _middleware._tcp.local. PTR freenas._middleware._tcp.local.
From that log I thought there was something wrong with middleware(Not sure what that is). Found these errors in that log during the shutdown times:
Code:
[2019/09/15 01:46:21] (DEBUG) VMService.run():288 - Ombi: Unhandled ps2 keyboard command 0xf6 [2019/09/15 01:46:21] (DEBUG) VMService.run():288 - Ombi: fbuf frame buffer base: 0x842e00000 [sz 16777216] [2019/09/15 01:46:21] (INFO) VMService.run():305 - ===> Powered off VM: Ombi ID: 3 BHYVE_CODE: 1 [2019/09/15 01:46:22] (ERROR) VMService.running():445 - ===> VMM Ombi is running without bhyve process. [2019/09/15 01:46:22] (DEBUG) VMService.__teardown_guest_vmemory():342 - ===> Give back guest memory to ARC: 64661008384 [2019/09/15 01:46:22] (WARNING) VMService.destroy_vm():320 - ===> Destroying VM: Ombi ID: 3 BHYVE_CODE: 1 [2019/09/15 01:46:22] (DEBUG) VMService.kill_bhyve_web():413 - ==> Killing WEBVNC: 4974 [2019/09/15 01:46:22] (WARNING) middlewared.devd_loop():70 - devd pipe error, retrying... Traceback (most recent call last): File "/usr/local/lib/python3.6/site-packages/middlewared/plugins/device.py", line 68, in devd_loop await devd_listen(middleware) File "/usr/local/lib/python3.6/site-packages/middlewared/plugins/device.py", line 92, in devd_listen s.connect(DEVD_SOCKETFILE) ConnectionRefusedError: [Errno 61] Connection refused [2019/09/14 18:46:22] (DEBUG) JailService.stop_on_shutdown():1022 - Stopping jails on shutdown: PENDING [2019/09/14 18:46:22] (INFO) iocage.callback():54 - Stopping radarr [2019/09/14 18:46:23] (INFO) iocage.callback():54 - * Stopping radarr [2019/09/14 18:46:23] (INFO) iocage.callback():54 - + Running prestop OK [2019/09/14 18:46:23] (INFO) iocage.callback():54 - + Stopping services OK [2019/09/14 18:46:23] (INFO) iocage.callback():54 - + Tearing down VNET OK [2019/09/14 18:46:23] (INFO) iocage.callback():54 - + Removing devfs_ruleset: 6 OK [2019/09/14 18:46:23] (INFO) iocage.callback():54 - + Removing jail process OK [2019/09/14 18:46:23] (INFO) iocage.callback():54 - + Running poststop OK [2019/09/14 18:46:23] (INFO) iocage.callback():54 - Stopping mineos [2019/09/14 18:46:23] (INFO) iocage.callback():54 - * Stopping mineos [2019/09/14 18:46:23] (INFO) iocage.callback():54 - + Running prestop OK [2019/09/15 01:46:23] (WARNING) middlewared.devd_loop():70 - devd pipe error, retrying... Traceback (most recent call last): File "/usr/local/lib/python3.6/site-packages/middlewared/plugins/device.py", line 68, in devd_loop await devd_listen(middleware) File "/usr/local/lib/python3.6/site-packages/middlewared/plugins/device.py", line 92, in devd_listen s.connect(DEVD_SOCKETFILE) ConnectionRefusedError: [Errno 61] Connection refused [2019/09/14 18:46:23] (INFO) iocage.callback():54 - + Stopping services OK [2019/09/14 18:46:23] (INFO) iocage.callback():54 - + Tearing down VNET OK [2019/09/14 18:46:23] (INFO) iocage.callback():54 - + Removing devfs_ruleset: 9 OK [2019/09/14 18:46:23] (INFO) iocage.callback():54 - + Removing jail process OK [2019/09/14 18:46:23] (INFO) iocage.callback():54 - + Running poststop OK [2019/09/14 18:46:23] (INFO) iocage.callback():54 - Stopping sonarr [2019/09/14 18:46:23] (INFO) iocage.callback():54 - * Stopping sonarr [2019/09/14 18:46:23] (INFO) iocage.callback():54 - + Running prestop OK [2019/09/14 18:46:23] (INFO) iocage.callback():54 - + Stopping services OK [2019/09/14 18:46:23] (INFO) iocage.callback():54 - + Tearing down VNET OK [2019/09/14 18:46:23] (INFO) iocage.callback():54 - + Removing devfs_ruleset: 5 OK [2019/09/14 18:46:23] (INFO) iocage.callback():54 - + Removing jail process OK [2019/09/14 18:46:23] (INFO) iocage.callback():54 - + Running poststop OK [2019/09/14 18:46:23] (INFO) iocage.callback():54 - Stopping NZBGet [2019/09/14 18:46:23] (INFO) iocage.callback():54 - * Stopping NZBGet [2019/09/14 18:46:23] (INFO) iocage.callback():54 - + Running prestop OK [2019/09/14 18:46:23] (INFO) iocage.callback():54 - + Stopping services OK [2019/09/14 18:46:23] (INFO) iocage.callback():54 - + Tearing down VNET OK [2019/09/14 18:46:23] (INFO) iocage.callback():54 - + Removing devfs_ruleset: 7 OK [2019/09/14 18:46:23] (INFO) iocage.callback():54 - + Removing jail process OK [2019/09/14 18:46:23] (INFO) iocage.callback():54 - + Running poststop OK [2019/09/14 18:46:23] (INFO) iocage.callback():54 - Stopping plex-plexpass [2019/09/14 18:46:24] (INFO) iocage.callback():54 - * Stopping plex-plexpass [2019/09/14 18:46:24] (INFO) iocage.callback():54 - + Running prestop OK [2019/09/14 18:46:24] (INFO) iocage.callback():54 - + Stopping services OK [2019/09/14 18:46:24] (INFO) iocage.callback():54 - + Tearing down VNET OK [2019/09/14 18:46:24] (INFO) iocage.callback():54 - + Removing devfs_ruleset: 8 OK [2019/09/15 01:46:24] (WARNING) middlewared.devd_loop():70 - devd pipe error, retrying... Traceback (most recent call last): File "/usr/local/lib/python3.6/site-packages/middlewared/plugins/device.py", line 68, in devd_loop await devd_listen(middleware) File "/usr/local/lib/python3.6/site-packages/middlewared/plugins/device.py", line 92, in devd_listen s.connect(DEVD_SOCKETFILE) ConnectionRefusedError: [Errno 61] Connection refused [2019/09/15 01:46:25] (WARNING) middlewared.devd_loop():70 - devd pipe error, retrying... Traceback (most recent call last): File "/usr/local/lib/python3.6/site-packages/middlewared/plugins/device.py", line 68, in devd_loop await devd_listen(middleware) File "/usr/local/lib/python3.6/site-packages/middlewared/plugins/device.py", line 92, in devd_listen s.connect(DEVD_SOCKETFILE) ConnectionRefusedError: [Errno 61] Connection refused [2019/09/15 01:46:26] (WARNING) middlewared.devd_loop():70 - devd pipe error, retrying... Traceback (most recent call last): File "/usr/local/lib/python3.6/site-packages/middlewared/plugins/device.py", line 68, in devd_loop await devd_listen(middleware) File "/usr/local/lib/python3.6/site-packages/middlewared/plugins/device.py", line 92, in devd_listen s.connect(DEVD_SOCKETFILE) ConnectionRefusedError: [Errno 61] Connection refused [2019/09/15 01:46:27] (WARNING) middlewared.devd_loop():70 - devd pipe error, retrying... Traceback (most recent call last): File "/usr/local/lib/python3.6/site-packages/middlewared/plugins/device.py", line 68, in devd_loop await devd_listen(middleware) File "/usr/local/lib/python3.6/site-packages/middlewared/plugins/device.py", line 92, in devd_listen s.connect(DEVD_SOCKETFILE) ConnectionRefusedError: [Errno 61] Connection refused [2019/09/15 01:46:28] (WARNING) middlewared.devd_loop():70 - devd pipe error, retrying... Traceback (most recent call last): File "/usr/local/lib/python3.6/site-packages/middlewared/plugins/device.py", line 68, in devd_loop await devd_listen(middleware) File "/usr/local/lib/python3.6/site-packages/middlewared/plugins/device.py", line 92, in devd_listen s.connect(DEVD_SOCKETFILE) ConnectionRefusedError: [Errno 61] Connection refused [2019/09/15 01:46:29] (WARNING) middlewared.devd_loop():70 - devd pipe error, retrying... Traceback (most recent call last): File "/usr/local/lib/python3.6/site-packages/middlewared/plugins/device.py", line 68, in devd_loop await devd_listen(middleware) File "/usr/local/lib/python3.6/site-packages/middlewared/plugins/device.py", line 92, in devd_listen s.connect(DEVD_SOCKETFILE) ConnectionRefusedError: [Errno 61] Connection refused