Another Freenas won't gracefully shutdown thread

B

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

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
 
D

dlavigne

Guest
Is the BIOS at the latest version? Which plugins are running?
 
B

blueberryjr

Dabbler
Joined
Sep 7, 2017
Messages
15
Good question on the bios, I haven't checked yet. I'm out of town at the moment, will check in a few days when I get back. As far as plugins, I have mineos, plexpass,deluge, radarr and sonarr running but I have tested this with them all disabled as well
 
D

dlavigne

Guest
If the BIOS turns out to be at the latest version, I would suspect one of the plugin apps to be ignoring the shutdown message. Would be interesting to see if a shutdown occurs successfully if all plugins are stopped first.
 
B

blueberryjr

Dabbler
Joined
Sep 7, 2017
Messages
15
I have shutdown freenas with all of the plugins disabled/turned off and same errors showed up. I updated the bios last night when I got home from my work trip. After updating freenas would not successfully boot. So it looks like I have to choose between successful boot or successful shutdown.
I had to roll it back down to the old version which is from fall 2018. I will try reinstalling freenas with the new bios tonight and see how that goes.
 
B

blueberryjr

Dabbler
Joined
Sep 7, 2017
Messages
15
So I've tried for about a month to get freenas to work with the new bios update for my mobo but it doesn't seem to like it at all. I'm thinking it may just be incompatible. The installer for freenas won't boot either.
When issuing the shutdown command it gets past disabling swap and all of the drives spin down completely but usually gets stuck there as stated above. But I turned off all of the jails and took at look at the logs.

messages has this line listed about 6 times during shutdown

freenas.local python3.6: dnssd_clientstub DNSServiceProcessResult called with DNSServiceRef with no ProcessReply function

From daemon.log

Code:
Nov  9 14:36:34 freenas.local zfsd: Disconnecting from devd.
Nov  9 14:36:35 freenas.local mDNSResponder: mDNSResponder (Engineering Build) (Sep 16 2019 23:06:56) stopping
Nov  9 14:36:36 freenas.local smartd[3260]: smartd received signal 15: Terminated
Nov  9 14:36:36 freenas.local smartd[3260]: smartd is exiting (exit status 0)
Nov  9 14:36:36 freenas.local upsmon[3143]: Signal 15: exiting
Nov  9 14:36:36 freenas.local upsd[3135]: User upsmon@127.0.0.1 logged out from UPS [ups]
Nov  9 14:36:36 freenas.local upsmon[3141]: upsmon parent: read
Nov  9 14:36:36 freenas.local upslog[3138]: Signal 15: exiting
Nov  9 14:36:36 freenas.local upsd[3135]: mainloop: Interrupted system call
Nov  9 14:36:36 freenas.local upsd[3135]: Signal 15: exiting
Nov  9 14:36:36 freenas.local usbhid-ups[3133]: Signal 15: exiting
Nov  9 14:36:39 freenas.local mDNSResponder: mDNSResponder (Engineering Build) (Sep 16 2019 23:06:56) stopping
Nov  9 14:36:39 freenas.local mDNSResponder: mDNS_FinalExit failed to send goodbye for: 0000000801089580 01   25 _ssh._tcp.local. PTR freenas._ssh._tcp.local.
Nov  9 14:36:39 freenas.local mDNSResponder: mDNS_FinalExit failed to send goodbye for: 000000080108A980 01   30 _sftp-ssh._tcp.local. PTR freenas._sftp-ssh._tcp.local.
Nov  9 14:36:39 freenas.local mDNSResponder: mDNS_FinalExit failed to send goodbye for: 000000080108BD80 01   26 _http._tcp.local. PTR freenas._http._tcp.local.
Nov  9 14:36:39 freenas.local mDNSResponder: mDNS_FinalExit failed to send goodbye for: 000000080108D180 01   32 _middleware._tcp.local. PTR freenas._middleware._tcp.local.
Nov  9 14:40:31 freenas.local usbhid-ups[3127]: Startup successful


The mdnsresponder.log states the same errors.


From middleware.log from boot to shutdown signal at 14:36:34

Code:
[2019/11/09 22:25:06] (DEBUG) raven.base.Client.set_dsn():265 - Configuring Raven for host: https://sentry.ixsystems.com
[2019/11/09 22:25:08] (DEBUG) git.cmd.execute():719 - Popen(['git', 'version'], cwd=/, universal_newlines=False, shell=None)
[2019/11/09 22:25:08] (DEBUG) git.cmd.execute():719 - Popen(['git', 'version'], cwd=/, universal_newlines=False, shell=None)
[2019/11/09 22:25:09] (DEBUG) middlewared.__plugins_load():808 - All plugins loaded
[2019/11/09 22:25:09] (DEBUG) middlewared.__setup_periodic_tasks():821 - Setting up periodic task zfs.quota.notify_quota_excess to run every 60 seconds
[2019/11/09 22:25:09] (DEBUG) middlewared.__setup_periodic_tasks():821 - Setting up periodic task mail.send_mail_queue to run every 600 seconds
[2019/11/09 22:25:09] (DEBUG) middlewared.__setup_periodic_tasks():821 - Setting up periodic task alert.flush_alerts to run every 3600 seconds
[2019/11/09 22:25:09] (DEBUG) middlewared.__setup_periodic_tasks():821 - Setting up periodic task alert.process_alerts to run every 60 seconds
[2019/11/09 22:25:09] (DEBUG) middlewared.run():1267 - Accepting connections
[2019/11/09 22:25:09] (DEBUG) krb5.keytab.render():32 - No keytabs in configuration database, skipping keytab generation
[2019/11/09 22:25:28] (DEBUG) EtcService.generate():190 - No new changes for /etc/nsswitch.conf
[2019/11/09 22:25:28] (DEBUG) EtcService.generate():190 - No new changes for /etc/local/nss_ldap.conf
[2019/11/09 22:25:28] (DEBUG) EtcService.generate():190 - No new changes for /etc/pam.d/other
[2019/11/09 22:25:28] (DEBUG) EtcService.generate():190 - No new changes for /etc/pam.d/system
[2019/11/09 22:25:28] (DEBUG) EtcService.generate():190 - No new changes for /etc/pam.d/su
[2019/11/09 22:25:28] (DEBUG) EtcService.generate():190 - No new changes for /etc/pam.d/atrun
[2019/11/09 22:25:28] (DEBUG) EtcService.generate():190 - No new changes for /etc/pam.d/passwd
[2019/11/09 22:25:28] (DEBUG) EtcService.generate():190 - No new changes for /etc/pam.d/ftpd
[2019/11/09 22:25:28] (DEBUG) EtcService.generate():190 - No new changes for /etc/pam.d/pam.inc
[2019/11/09 22:25:28] (DEBUG) EtcService.generate():190 - No new changes for /etc/pam.d/README
[2019/11/09 22:25:28] (DEBUG) EtcService.generate():190 - No new changes for /etc/pam.d/telnetd
[2019/11/09 22:25:28] (DEBUG) EtcService.generate():190 - No new changes for /etc/pam.d/sudo
[2019/11/09 22:25:28] (DEBUG) EtcService.generate():190 - No new changes for /etc/pam.d/rsh
[2019/11/09 22:25:28] (DEBUG) EtcService.generate():190 - No new changes for /etc/pam.d/imap
[2019/11/09 22:25:28] (DEBUG) EtcService.generate():190 - No new changes for /etc/pam.d/sshd
[2019/11/09 22:25:28] (DEBUG) EtcService.generate():190 - No new changes for /etc/pam.d/login
[2019/11/09 22:25:28] (DEBUG) EtcService.generate():190 - No new changes for /etc/pam.d/netatalk
[2019/11/09 22:25:28] (DEBUG) EtcService.generate():190 - No new changes for /etc/pam.d/xdm
[2019/11/09 22:25:28] (DEBUG) EtcService.generate():190 - No new changes for /etc/pam.d/cron
[2019/11/09 22:25:28] (DEBUG) EtcService.generate():190 - No new changes for /etc/pam.d/kde
[2019/11/09 22:25:28] (DEBUG) EtcService.generate():190 - No new changes for /etc/pam.d/ftp
[2019/11/09 22:25:28] (DEBUG) EtcService.generate():190 - No new changes for /etc/pam.d/pop3
[2019/11/09 22:25:28] (DEBUG) EtcService.generate():190 - No new changes for /etc/pam.d/samba
[2019/11/09 22:25:29] (DEBUG) EtcService.generate():190 - No new changes for /etc/krb5.conf
[2019/11/09 22:25:29] (DEBUG) krb5.keytab.render():32 - No keytabs in configuration database, skipping keytab generation
[2019/11/09 22:25:38] (DEBUG) middleware.notifier._pipeopen():179 - Popen()ing: /sbin/zfs list -H -o name -t volume,filesystem
[2019/11/09 22:25:39] (DEBUG) middleware.notifier._pipeopen():179 - Popen()ing: /usr/local/bin/net groupmap list
[2019/11/09 22:27:10] (DEBUG) freenasOS.Configuration.TryGetNetworkFile():601 - TryGetNetworkFile(['https://update.ixsystems.com/FreeNAS/trains.txt', 'https://update-master.ixsystems.com/FreeNAS/trains.txt'])
[2019/11/09 22:27:10] (DEBUG) urllib3.connectionpool._new_conn():824 - Starting new HTTPS connection (1): update.ixsystems.com
[2019/11/09 22:27:11] (DEBUG) urllib3.connectionpool._make_request():396 - https://update.ixsystems.com:443 "GET /FreeNAS/trains.txt HTTP/1.1" 301 169
[2019/11/09 22:27:11] (DEBUG) urllib3.connectionpool._new_conn():824 - Starting new HTTPS connection (1): update.freenas.org
[2019/11/09 22:27:11] (DEBUG) urllib3.connectionpool._make_request():396 - https://update.freenas.org:443 "GET /FreeNAS/trains.txt HTTP/1.1" 200 507
[2019/11/09 22:27:11] (DEBUG) freenasOS.Configuration.TryGetNetworkFile():731 - TryGetNetworkFile(['https://update.ixsystems.com/FreeNAS/trains.txt', 'https://update-master.ixsystems.com/FreeNAS/trains.txt']):  Read 507 bytes total
[2019/11/09 22:27:11] (DEBUG) freenasOS.Configuration.TryGetNetworkFile():601 - TryGetNetworkFile(['https://update-master.ixsystems.com/FreeNAS/FreeNAS-11.2-STABLE/LATEST'])
[2019/11/09 22:27:11] (DEBUG) urllib3.connectionpool._new_conn():824 - Starting new HTTPS connection (1): update-master.ixsystems.com
[2019/11/09 22:27:11] (DEBUG) urllib3.connectionpool._make_request():396 - https://update-master.ixsystems.com:443 "GET /FreeNAS/FreeNAS-11.2-STABLE/LATEST HTTP/1.1" 200 1955
[2019/11/09 22:27:11] (DEBUG) freenasOS.Configuration.TryGetNetworkFile():731 - TryGetNetworkFile(['https://update-master.ixsystems.com/FreeNAS/FreeNAS-11.2-STABLE/LATEST']):  Read 1955 bytes total
[2019/11/09 22:27:11] (DEBUG) freenasOS.Configuration.TryGetNetworkFile():601 - TryGetNetworkFile(['https://update-master.ixsystems.com/updates/ix_crl.pem'])
[2019/11/09 22:27:11] (DEBUG) urllib3.connectionpool._new_conn():824 - Starting new HTTPS connection (1): update-master.ixsystems.com
[2019/11/09 22:27:12] (DEBUG) urllib3.connectionpool._make_request():396 - https://update-master.ixsystems.com:443 "GET /updates/ix_crl.pem HTTP/1.1" 200 1028
[2019/11/09 22:27:12] (DEBUG) freenasOS.Configuration.CheckFreeSpace():76 - CheckFreeSpace(path=/tmp/tmpitw0eiqr.pem, pool=None, required=1028)
[2019/11/09 22:27:12] (DEBUG) freenasOS.Configuration.TryGetNetworkFile():731 - TryGetNetworkFile(['https://update-master.ixsystems.com/updates/ix_crl.pem']):  Read 1028 bytes total
[2019/11/09 22:27:12] (DEBUG) freenasOS.Configuration.TryGetNetworkFile():601 - TryGetNetworkFile(['https://update.ixsystems.com/FreeNAS/Validators/ValidateUpdate-pcBO6C.txt', 'https://update-master.ixsystems.com/FreeNAS/Validators/ValidateUpdate-pcBO6C.txt'])
[2019/11/09 22:27:12] (DEBUG) urllib3.connectionpool._new_conn():824 - Starting new HTTPS connection (1): update.ixsystems.com
[2019/11/09 22:27:12] (DEBUG) urllib3.connectionpool._make_request():396 - https://update.ixsystems.com:443 "GET /FreeNAS/Validators/ValidateUpdate-pcBO6C.txt HTTP/1.1" 301 169
[2019/11/09 22:27:12] (DEBUG) urllib3.connectionpool._new_conn():824 - Starting new HTTPS connection (1): update.freenas.org
[2019/11/09 22:27:12] (DEBUG) urllib3.connectionpool._make_request():396 - https://update.freenas.org:443 "GET /FreeNAS/Validators/ValidateUpdate-pcBO6C.txt HTTP/1.1" 200 185
[2019/11/09 22:27:12] (DEBUG) freenasOS.Configuration.CheckFreeSpace():76 - CheckFreeSpace(path=/tmp/tmp93yhirmk, pool=None, required=185)
[2019/11/09 22:27:12] (DEBUG) freenasOS.Configuration.TryGetNetworkFile():731 - TryGetNetworkFile(['https://update.ixsystems.com/FreeNAS/Validators/ValidateUpdate-pcBO6C.txt', 'https://update-master.ixsystems.com/FreeNAS/Validators/ValidateUpdate-pcBO6C.txt']):  Read 185 bytes total
Exception in thread Thread-11:
Traceback (most recent call last):
  File "/usr/local/lib/python3.6/threading.py", line 916, in _bootstrap_inner
    self.run()
  File "/usr/local/lib/python3.6/site-packages/middlewared/plugins/mdns.py", line 303, in run
    pybonjour.DNSServiceProcessResult(ref)
  File "/usr/local/lib/python3.6/site-packages/pybonjour.py", line 895, in DNSServiceProcessResult
    _DNSServiceProcessResult(sdRef)
  File "/usr/local/lib/python3.6/site-packages/pybonjour.py", line 286, in _errcheck
    raise cls(result)
pybonjour.BonjourError: (-65541, 'bad reference')

[2019/11/09 22:36:38] (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/11/09 22:36:39] (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/11/09 22:36:39] (INFO) middlewared.terminate():1277 - Terminating
[2019/11/09 22:36:39] (INFO) middlewared.terminate():1277 - Terminating
[2019/11/09 22:36:39] (ERROR) asyncio.default_exception_handler():1285 - Task exception was never retrieved
future: <Task finished coro=<Middleware.__terminate() done, defined at /usr/local/lib/python3.6/site-packages/middlewared/main.py:1280> exception=CancelledError()>
concurrent.futures._base.CancelledError
 
You must log in or register to reply here.

Similar threads

T
smartctl -l scttemp output question
Replies
4
Views
2K
Chris Moore
Chris Moore
jjkester
  • Locked
FreeNAS 9.10 spontaneously reboots
Replies
3
Views
1K
jjkester
jjkester
thepixelgeek
Plex troubleshooting help / All of a sudden getting "Not Reachable"
Replies
4
Views
2K
thepixelgeek
thepixelgeek
R
  • Locked
FreeNAS 11.0-U3 Active Directory Down Enable After some time
Replies
7
Views
2K
razor1299
R
H
  • Locked
time going out of sync
Replies
5
Views
2K
hotdog
H
Top