[RESOLVED] TrueNAS GUI inaccessible, middlewared socket connect error

[apwiggins]

In the last couple of days, I've had the GUI become inaccessible. /var/log/messages has this socket error:

Code:

Dec  4 00:00:00 freenas2 syslog-ng[2923]: Configuration reload request received, reloading configuration;
Dec  4 00:00:00 freenas2 syslog-ng[2923]: Configuration reload finished;
Dec  4 13:18:17 freenas2 ipmi0: KCS: Failed to write data byte 2
Dec  4 13:18:17 freenas2 ipmi0: KCS error: 77
Dec  4 16:31:25 freenas2 kernel: pid 1860 (python3.8), jid 0, uid 0: exited on signal 11 (core dumped)
Dec  4 16:33:10 freenas2 1 2020-12-04T16:33:10.718603-04:00 freenas2.local collectd 3264 - - Traceback (most recent call last):
  File "/usr/local/lib/collectd_pyplugins/disktemp.py", line 62, in read
    with Client() as c:
  File "/usr/local/lib/python3.8/site-packages/middlewared/client/client.py", line 281, in __init__
    self._ws.connect()
  File "/usr/local/lib/python3.8/site-packages/middlewared/client/client.py", line 124, in connect
    rv = super(WSClient, self).connect()
  File "/usr/local/lib/python3.8/site-packages/ws4py/client/__init__.py", line 216, in connect
    self.sock.connect(self.bind_addr)
ConnectionRefusedError: [Errno 61] Connection refused

A reboot seems to resolve the problem. When ssh'ing into the box, there is also this similar error.

Code:

ssh root@x.x.x.x
FreeBSD 12.2-RC3 7c4ec6ff02c(HEAD) TRUENAS

    TrueNAS (c) 2009-2020, iXsystems, Inc.
    All rights reserved.
    TrueNAS code is released under the modified BSD license with some
    files copyrighted by (c) iXsystems, Inc.

    For more information, documentation, help or support, go here:
    http://truenas.com
Welcome to FreeNAS
Traceback (most recent call last):
  File "/usr/local/sbin/hactl", line 171, in <module>
    main(args.command, args.q)
  File "/usr/local/sbin/hactl", line 17, in main
    client = Client()
  File "/usr/local/lib/python3.8/site-packages/middlewared/client/client.py", line 281, in __init__
    self._ws.connect()
  File "/usr/local/lib/python3.8/site-packages/middlewared/client/client.py", line 124, in connect
    rv = super(WSClient, self).connect()
  File "/usr/local/lib/python3.8/site-packages/ws4py/client/__init__.py", line 216, in connect
    self.sock.connect(self.bind_addr)
ConnectionRefusedError: [Errno 61] Connection refused

Warning: settings changed through the CLI are not written to
the configuration database and will be reset on reboot.

root@freenas2:~ #

 

[Dopamin3]

The GUI on TrueNAS 12.0-RELEASE has been flaky for me, issues loading in general and especially with starting VMs if they are powered off. What fixes it for me is just doing a "service middlewared restart"- you might be able to do this rather than reboot the entire machine.

 

[apwiggins]

The GUI on TrueNAS 12.0-RELEASE has been flaky for me, issues loading in general and especially with starting VMs if they are powered off. What fixes it for me is just doing a "service middlewared restart"- you might be able to do this rather than reboot the entire machine.

Makes sense. I didn't realize middlewared was a service. Thanks for the tip.

 

[Fred.]

I'm also running into this. I think it happens when your session expires.
Thanks for the tip to restart middlewared

 

[apwiggins]

There's also a side effect where VMs seem to drop off the net too. I run a bunch of docker containers in a Clear Linux iohyve VM, so services dropped out from these containers. Once middlewared was restarted, the containers reappeared.

 

[apwiggins]

Upgraded now to 12.0-U2 and starting to see some middlewared issues again. GUI was hung and /etc/netcli wouldn't connect. Ultimately restarting middlewared resolved the issue. Posting resolution for others who have similar problems.

Code:

Console setup
-------------

1) Configure Network Interfaces
2) Configure Link Aggregation
3) Configure VLAN Interface
4) Configure Default Route
5) Configure Static Routes
6) Configure DNS
7) Reset Root Password
8) Reset Configuration to Defaults
9) Shell
10) Reboot
11) Shut Down
Enter an option from 1-11: 9
Traceback (most recent call last):
  File "/usr/local/sbin/hactl", line 171, in <module>
    main(args.command, args.q)
  File "/usr/local/sbin/hactl", line 17, in main
    client = Client()
  File "/usr/local/lib/python3.8/site-packages/middlewared/client/client.py", line 281, in __init__
    self._ws.connect()
  File "/usr/local/lib/python3.8/site-packages/middlewared/client/client.py", line 124, in connect
    rv = super(WSClient, self).connect()
  File "/usr/local/lib/python3.8/site-packages/ws4py/client/__init__.py", line 216, in connect
    self.sock.connect(self.bind_addr)
ConnectionRefusedError: [Errno 61] Connection refused

Warning: settings changed through the CLI are not written to
the configuration database and will be reset on reboot.

root@freenas2:~ # service middlewared stop
Stopping middlewared.
Waiting for PIDS: 1857.
root@freenas2:~ # service middlewared start

 

[pschatz100]

Please provide a detailed description of your system. It is not possible to offer insightful comments without any information.

 

[apwiggins]

Please provide a detailed description of your system. It is not possible to offer insightful comments without any information.

Well, that's a pretty open-ended request. So to start scoping what information you might actually be looking for, I'll ask you a question first. What are the stressors of middlewared such that it hangs and blocks socket connections from its command line client (/etc/ncli)?

/var/logs/middlewared.log. The logs between 15 Feb (likely when it hung) and 19 Feb (when middleward was restarted) are noted below.

Code:

[2021/02/15 05:30:00] (DEBUG) EtcService.generate():378 - No new changes for /etc/krb5.conf
[2021/02/15 05:30:00] (DEBUG) EtcService.generate():378 - No new changes for /etc/krb5.conf
[2021/02/15 08:44:50] (DEBUG) urllib3.connectionpool._new_conn():955 - Starting new HTTPS connection (1): update-master.ixsystems.com:443
[2021/02/15 08:44:51] (DEBUG) urllib3.connectionpool._make_request():428 - https://update-master.ixsystems.com:443 "GET /TrueNAS/trains_redir.json HTTP/1.1" 200 233
[2021/02/15 08:44:51] (DEBUG) freenasOS.Configuration.TryGetNetworkFile():606 - TryGetNetworkFile(['https://update.ixsystems.com/TrueNAS/trains.txt', 'https://update-master.ixsystems.com/TrueNAS/trains.txt'])
[2021/02/15 08:44:51] (DEBUG) urllib3.connectionpool._new_conn():955 - Starting new HTTPS connection (1): update.ixsystems.com:443
[2021/02/15 08:44:51] (DEBUG) urllib3.connectionpool._make_request():428 - https://update.ixsystems.com:443 "GET /TrueNAS/trains.txt HTTP/1.1" 301 169
[2021/02/15 08:44:51] (DEBUG) urllib3.connectionpool._new_conn():955 - Starting new HTTPS connection (1): update.freenas.org:443
[2021/02/15 08:44:52] (DEBUG) urllib3.connectionpool._make_request():428 - https://update.freenas.org:443 "GET /TrueNAS/trains.txt HTTP/1.1" 200 377
[2021/02/15 08:44:52] (DEBUG) freenasOS.Configuration.TryGetNetworkFile():745 - TryGetNetworkFile(['https://update.ixsystems.com/TrueNAS/trains.txt', 'https://update-master.ixsystems.com/TrueNAS/trains.txt']):  Read 377 bytes total
[2021/02/15 08:44:52] (DEBUG) freenasOS.Configuration.TryGetNetworkFile():606 - TryGetNetworkFile(['https://update-master.ixsystems.com/TrueNAS/TrueNAS-12.0-STABLE/LATEST'])
[2021/02/15 08:44:52] (DEBUG) urllib3.connectionpool._new_conn():955 - Starting new HTTPS connection (1): update-master.ixsystems.com:443
[2021/02/15 08:44:52] (DEBUG) urllib3.connectionpool._make_request():428 - https://update-master.ixsystems.com:443 "GET /TrueNAS/TrueNAS-12.0-STABLE/LATEST HTTP/1.1" 200 1602
[2021/02/15 08:44:52] (DEBUG) freenasOS.Configuration.TryGetNetworkFile():745 - TryGetNetworkFile(['https://update-master.ixsystems.com/TrueNAS/TrueNAS-12.0-STABLE/LATEST']):  Read 1602 bytes total
[2021/02/15 08:44:52] (DEBUG) freenasOS.Configuration.TryGetNetworkFile():606 - TryGetNetworkFile(['https://update-master.ixsystems.com/updates/ix_crl.pem'])
[2021/02/15 08:44:52] (DEBUG) urllib3.connectionpool._new_conn():955 - Starting new HTTPS connection (1): update-master.ixsystems.com:443
[2021/02/15 08:44:52] (DEBUG) urllib3.connectionpool._make_request():428 - https://update-master.ixsystems.com:443 "GET /updates/ix_crl.pem HTTP/1.1" 200 1028
[2021/02/15 08:44:52] (DEBUG) freenasOS.Configuration.CheckFreeSpace():77 - CheckFreeSpace(path=/tmp/tmpxh8hcqa6.pem, pool=None, required=1028)
[2021/02/15 08:44:52] (DEBUG) freenasOS.Configuration.TryGetNetworkFile():745 - TryGetNetworkFile(['https://update-master.ixsystems.com/updates/ix_crl.pem']):  Read 1028 bytes total
[2021/02/15 08:44:52] (DEBUG) freenasOS.Configuration.TryGetNetworkFile():606 - TryGetNetworkFile(['https://update.ixsystems.com/TrueNAS/Validators/ValidateUpdate-mg3ef525.txt', 'https://update-master.ixsystems.com/TrueNAS/Validators/ValidateUpdate-mg3ef525.txt'])
[2021/02/15 08:44:52] (DEBUG) urllib3.connectionpool._new_conn():955 - Starting new HTTPS connection (1): update.ixsystems.com:443
[2021/02/15 08:44:53] (DEBUG) urllib3.connectionpool._make_request():428 - https://update.ixsystems.com:443 "GET /TrueNAS/Validators/ValidateUpdate-mg3ef525.txt HTTP/1.1" 301 169
[2021/02/15 08:44:53] (DEBUG) urllib3.connectionpool._new_conn():955 - Starting new HTTPS connection (1): update.freenas.org:443
[2021/02/15 08:44:53] (DEBUG) urllib3.connectionpool._make_request():428 - https://update.freenas.org:443 "GET /TrueNAS/Validators/ValidateUpdate-mg3ef525.txt HTTP/1.1" 200 185
[2021/02/15 08:44:53] (DEBUG) freenasOS.Configuration.CheckFreeSpace():77 - CheckFreeSpace(path=/tmp/tmp5ajhe2_a, pool=None, required=185)
[2021/02/15 08:44:53] (DEBUG) freenasOS.Configuration.TryGetNetworkFile():745 - TryGetNetworkFile(['https://update.ixsystems.com/TrueNAS/Validators/ValidateUpdate-mg3ef525.txt', 'https://update-master.ixsystems.com/TrueNAS/Validators/ValidateUpdate-mg3ef525.txt']):  Read 185 bytes total
[2021/02/19 17:15:57] (INFO) middlewared.__init__():792 - Starting TrueNAS-12.0-U2 middleware
[2021/02/19 17:16:02] (DEBUG) middlewared.setup():1639 - Timezone set to America/Halifax
[2021/02/19 17:16:04] (WARNING) middlewared.send_event():1329 - Event 'failover.status' not registered.
[2021/02/19 17:16:09] (DEBUG) middlewared.setup():2835 - Certificate setup for System complete
[2021/02/19 17:16:09] (INFO) middlewared.devd_listen():58 - devd connection established
[2021/02/19 17:16:09] (DEBUG) middlewared.setup():135 - Setting link address '70:e2:84:13:ba:67' for interface 'vlan10'
[2021/02/19 17:16:09] (DEBUG) middlewared.setup():135 - Setting link address '02:45:89:7a:3a:0a' for interface 'bridge10'
[2021/02/19 17:16:09] (DEBUG) middlewared.__plugins_setup():907 - All plugins loaded
[2021/02/19 17:16:09] (DEBUG) middlewared._setup_periodic_tasks():920 - Setting up periodic task alert.flush_alerts to run every 3600 seconds
[2021/02/19 17:16:09] (DEBUG) middlewared._setup_periodic_tasks():920 - Setting up periodic task alert.process_alerts to run every 60 seconds
[2021/02/19 17:16:09] (DEBUG) middlewared._setup_periodic_tasks():920 - Setting up periodic task certificate.renew_certs to run every 86400 seconds
[2021/02/19 17:16:09] (DEBUG) middlewared._setup_periodic_tasks():920 - Setting up periodic task certificateauthority.crl_generation to run every 86400 seconds
[2021/02/19 17:16:09] (DEBUG) middlewared._setup_periodic_tasks():920 - Setting up periodic task kerberos.keytab.check_updated_keytab to run every 3600 seconds
[2021/02/19 17:16:09] (DEBUG) middlewared._setup_periodic_tasks():920 - Setting up periodic task kmip.sync_keys to run every 86400 seconds
[2021/02/19 17:16:09] (DEBUG) middlewared._setup_periodic_tasks():920 - Setting up periodic task mail.send_mail_queue to run every 600 seconds
[2021/02/19 17:16:09] (DEBUG) middlewared._setup_periodic_tasks():920 - Setting up periodic task plugin.periodic_plugin_update to run every 86400 seconds
[2021/02/19 17:16:09] (DEBUG) middlewared._setup_periodic_tasks():920 - Setting up periodic task plugin.retrieve_versions_for_repos to run every 86400 seconds
[2021/02/19 17:16:09] (DEBUG) middlewared._setup_periodic_tasks():920 - Setting up periodic task pool.dataset.sync_db_keys to run every 86400 seconds
[2021/02/19 17:16:09] (DEBUG) middlewared._setup_periodic_tasks():920 - Setting up periodic task smb.sharesec.check_share_info_tdb to run every 3600 seconds
[2021/02/19 17:16:09] (DEBUG) middlewared._setup_periodic_tasks():920 - Setting up periodic task truecommand.health_check to run every 1800 seconds
[2021/02/19 17:16:09] (DEBUG) middlewared._setup_periodic_tasks():920 - Setting up periodic task zettarepl.flush_state to run every 3600 seconds
[2021/02/19 17:16:09] (DEBUG) middlewared.__initialize():1499 - Accepting connections

 

[pschatz100]

Well, that's a pretty open-ended request. So to start scoping what information you might actually be looking for, I'll ask you a question first. What are the stressors of middlewared such that it hangs and blocks socket connections from its command line client (/etc/ncli)?

Actually, it is a pretty specific request, as detailed by the forum rules when posting an issue. You will see that the majority of users on the site, including me, post a description of their system.