Project

General

Profile

Bug #54132

Fix traceback on first boot without jails/plugins

Added by Bug Clerk over 1 year ago. Updated over 1 year ago.

Status:
Done
Priority:
No priority
Assignee:
William Grzybowski
Category:
Middleware
Target version:
Seen in:
Severity:
Low Medium
Reason for Closing:
Reason for Blocked:
Needs QA:
No
Needs Doc:
No
Needs Merging:
No
Needs Automation:
No
Support Suite Ticket:
n/a
Hardware Configuration:
ChangeLog Required:
No

Description

future: <Task finished coro=<__event_system() done, defined at /usr/local/lib/python3.7/site-packages/middlewared/plugins/jail.py:1004> exception=PoolNotActivated('Please specify a pool to activate with iocage activate POOL')>
concurrent.futures.process._RemoteTraceback: 
""" 
Traceback (most recent call last):
  File "/usr/local/lib/python3.7/site-packages/iocage_lib/ioc_json.py", line 531, in json_get_value
    zpool = zpools[1]
IndexError: list index out of range

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/usr/local/lib/python3.7/concurrent/futures/process.py", line 232, in _process_worker
    r = call_item.fn(*call_item.args, **call_item.kwargs)
  File "/usr/local/lib/python3.7/site-packages/middlewared/worker.py", line 95, in main_worker
    res = loop.run_until_complete(coro)
  File "/usr/local/lib/python3.7/asyncio/base_events.py", line 568, in run_until_complete
    return future.result()
  File "/usr/local/lib/python3.7/site-packages/middlewared/worker.py", line 55, in _run
    return await self._call(f'{service_name}.{method}', serviceobj, methodobj, params=args, job=job)
  File "/usr/local/lib/python3.7/site-packages/middlewared/worker.py", line 48, in _call
    return methodobj(*params)
  File "/usr/local/lib/python3.7/site-packages/middlewared/worker.py", line 48, in _call
    return methodobj(*params)
  File "/usr/local/lib/python3.7/site-packages/middlewared/plugins/jail.py", line 971, in start_on_boot
    ioc.IOCage(rc=True).start()
  File "/usr/local/lib/python3.7/site-packages/iocage_lib/iocage.py", line 115, in __init__
    self.pool = PoolAndDataset().get_pool()
  File "/usr/local/lib/python3.7/site-packages/iocage_lib/iocage.py", line 54, in __init__
    self.pool = ioc_json.IOCJson().json_get_value("pool")
  File "/usr/local/lib/python3.7/site-packages/iocage_lib/ioc_json.py", line 541, in json_get_value
    exception=ioc_exceptions.PoolNotActivated)
  File "/usr/local/lib/python3.7/site-packages/iocage_lib/ioc_common.py", line 85, in logit
    callback(content, exception)
  File "/usr/local/lib/python3.7/site-packages/iocage_lib/ioc_common.py", line 66, in callback
    raise callback_exception(message)
iocage_lib.ioc_exceptions.PoolNotActivated: Please specify a pool to activate with iocage activate POOL
""" 

The above exception was the direct cause of the following exception:

Traceback (most recent call last):
  File "/usr/local/lib/python3.7/site-packages/middlewared/plugins/jail.py", line 1012, in __event_system
    await middleware.call('jail.start_on_boot')
  File "/usr/local/lib/python3.7/site-packages/middlewared/main.py", line 1028, in call
    return await self._call(name, serviceobj, methodobj, params, app=app, pipes=pipes, io_thread=True)
  File "/usr/local/lib/python3.7/site-packages/middlewared/main.py", line 962, in _call
    return await self._call_worker(serviceobj, name, *args)
  File "/usr/local/lib/python3.7/site-packages/middlewared/main.py", line 988, in _call_worker
    job,
  File "/usr/local/lib/python3.7/site-packages/middlewared/main.py", line 920, in run_in_proc
    return await self.run_in_executor(self.__procpool, method, *args, **kwargs)
  File "/usr/local/lib/python3.7/site-packages/middlewared/main.py", line 905, in run_in_executor
    return await loop.run_in_executor(pool, functools.partial(method, *args, **kwargs))
iocage_lib.ioc_exceptions.PoolNotActivated: Please specify a pool to activate with iocage activate POOL

Acceptance Criteria
After a fresh install traceback above should not be shown in middlewared.log


Related issues

Copied from FreeNAS - Bug #53883: Fix traceback on first boot without jails/pluginsDone

History

#1 Updated by Bug Clerk over 1 year ago

  • Copied from Bug #53883: Fix traceback on first boot without jails/plugins added

#2 Updated by Bug Clerk over 1 year ago

  • Target version changed from Master - FreeNAS Nightlies to 11.2-RC2

#3 Updated by Bug Clerk over 1 year ago

  • Status changed from Unscreened to In Progress

#4 Updated by Bug Clerk over 1 year ago

  • Status changed from In Progress to Ready for Testing

#5 Updated by Dru Lavigne over 1 year ago

  • Needs Doc changed from Yes to No

#6 Updated by Jeff Ervin over 1 year ago

  • Status changed from Ready for Testing to Passed Testing
  • Needs QA changed from Yes to No

Test Passed FreeNAS-11.2-INTERNAL30 (Fresh install of INTERNAL 30 / No plugins/No Jails)

[root@freenas ~]# cat /var/log/middlewared.log
[2018/10/29 19:52:43] (DEBUG) raven.base.Client.set_dsn():265 - Configuring Raven for host: https://sentry.ixsystems.com
[2018/10/29 19:52:43] (DEBUG) middlewared.__plugins_load():766 - Loading plugins from /usr/local/lib/python3.6/site-packages/middlewared/plugins
[2018/10/29 19:52:49] (DEBUG) middlewared.__plugins_load():809 - All plugins loaded
[2018/10/29 19:52:50] (DEBUG) middlewared.__setup_periodic_tasks():822 - Setting up periodic task zfs.quota.notify_quota_excess to run every 60 seconds
[2018/10/29 19:52:50] (DEBUG) middlewared.__setup_periodic_tasks():822 - Setting up periodic task alert.flush_alerts to run every 3600 seconds
[2018/10/29 19:52:50] (DEBUG) middlewared.__setup_periodic_tasks():822 - Setting up periodic task alert.process_alerts to run every 60 seconds
[2018/10/29 19:52:50] (DEBUG) middlewared.__setup_periodic_tasks():822 - Setting up periodic task mail.send_mail_queue to run every 600 seconds
[2018/10/29 19:52:51] (DEBUG) middlewared.run():1194 - Accepting connections
[2018/10/29 19:52:53] (DEBUG) common.freenasldap.__init__():2467 - FreeNAS_ActiveDirectory.__init__: enter
[2018/10/29 19:52:53] (DEBUG) common.freenasldap.__init__():1559 - FreeNAS_ActiveDirectory_Base.__init__: enter
[2018/10/29 19:52:53] (DEBUG) common.freenasldap.__set_defaults():1406 - FreeNAS_ActiveDirectory_Base.__set_defaults: enter
[2018/10/29 19:52:53] (DEBUG) common.freenasldap.__set_defaults():1442 - FreeNAS_ActiveDirectory_Base.__set_defaults: leave
[2018/10/29 19:52:54] (DEBUG) smartd.ensure_smart_enabled():29 - SMART is not supported on ['/dev/ada0']
[2018/10/29 19:52:54] (DEBUG) smartd.ensure_smart_enabled():29 - SMART is not supported on ['/dev/da0']
[2018/10/29 19:53:07] (DEBUG) EtcService.generate():186 - No new changes for /etc/nsswitch.conf
[2018/10/29 19:53:08] (DEBUG) EtcService.generate():186 - No new changes for /etc/local/nss_ldap.conf
[2018/10/29 19:53:08] (DEBUG) EtcService.generate():186 - No new changes for /etc/pam.d/pam.inc
[2018/10/29 19:53:08] (DEBUG) EtcService.generate():186 - No new changes for /etc/pam.d/cron
[2018/10/29 19:53:08] (DEBUG) EtcService.generate():186 - No new changes for /etc/pam.d/ftp
[2018/10/29 19:53:08] (DEBUG) EtcService.generate():186 - No new changes for /etc/pam.d/netatalk
[2018/10/29 19:53:08] (DEBUG) EtcService.generate():186 - No new changes for /etc/pam.d/samba
[2018/10/29 19:53:08] (DEBUG) EtcService.generate():186 - No new changes for /etc/pam.d/kde
[2018/10/29 19:53:08] (DEBUG) EtcService.generate():186 - No new changes for /etc/pam.d/pop3
[2018/10/29 19:53:08] (DEBUG) EtcService.generate():186 - No new changes for /etc/pam.d/xdm
[2018/10/29 19:53:08] (DEBUG) EtcService.generate():186 - No new changes for /etc/pam.d/su
[2018/10/29 19:53:08] (DEBUG) EtcService.generate():186 - No new changes for /etc/pam.d/login
[2018/10/29 19:53:08] (DEBUG) EtcService.generate():186 - No new changes for /etc/pam.d/telnetd
[2018/10/29 19:53:08] (DEBUG) EtcService.generate():186 - No new changes for /etc/pam.d/sshd
[2018/10/29 19:53:08] (DEBUG) EtcService.generate():186 - No new changes for /etc/pam.d/rsh
[2018/10/29 19:53:08] (DEBUG) EtcService.generate():186 - No new changes for /etc/pam.d/README
[2018/10/29 19:53:08] (DEBUG) EtcService.generate():186 - No new changes for /etc/pam.d/sudo
[2018/10/29 19:53:08] (DEBUG) EtcService.generate():186 - No new changes for /etc/pam.d/imap
[2018/10/29 19:53:08] (DEBUG) EtcService.generate():186 - No new changes for /etc/pam.d/atrun
[2018/10/29 19:53:08] (DEBUG) EtcService.generate():186 - No new changes for /etc/pam.d/passwd
[2018/10/29 19:53:08] (DEBUG) EtcService.generate():186 - No new changes for /etc/pam.d/other
[2018/10/29 19:53:08] (DEBUG) EtcService.generate():186 - No new changes for /etc/pam.d/system
[2018/10/29 19:53:08] (DEBUG) EtcService.generate():186 - No new changes for /etc/pam.d/ftpd
[2018/10/29 19:53:13] (DEBUG) middleware.notifier._pipeopen():178 - Popen()ing:/sbin/zfs list -H -o name -t volume,filesystem
[2018/10/29 19:53:14] (DEBUG) middleware.notifier._pipeopen():178 - Popen()ing:/usr/local/bin/net groupmap list
[2018/10/29 19:55:05] (DEBUG) freenasOS.Configuration.TryGetNetworkFile():693 -TryGetNetworkFile(['http://update.ixsystems.com/FreeNAS/trains.txt', 'http://update-master.ixsystems.com/FreeNAS/trains.txt'])
[2018/10/29 19:55:07] (DEBUG) freenasOS.Configuration.TryGetNetworkFile():823 -TryGetNetworkFile(['http://update.ixsystems.com/FreeNAS/trains.txt', 'http://update-master.ixsystems.com/FreeNAS/trains.txt']): Read 456 bytes total
[2018/10/29 19:55:07] (DEBUG) freenasOS.Configuration.TryGetNetworkFile():693 -TryGetNetworkFile(['http://update-master.ixsystems.com/FreeNAS/FreeNAS-11.2-STABLE/LATEST'])
[2018/10/29 19:55:07] (DEBUG) freenasOS.Configuration.TryGetNetworkFile():823 -TryGetNetworkFile(['http://update-master.ixsystems.com/FreeNAS/FreeNAS-11.2-STABLE/LATEST']): Read 2239 bytes total
[2018/10/29 19:55:07] (DEBUG) freenasOS.Configuration.TryGetNetworkFile():693 -TryGetNetworkFile(['http://update-master.ixsystems.com/updates/ix_crl.pem'])
[2018/10/29 19:55:07] (DEBUG) freenasOS.Configuration.CheckFreeSpace():84 - CheckFreeSpace(path=/tmp/tmptyx029uh.pem, pool=None, required=1028)
[2018/10/29 19:55:07] (DEBUG) freenasOS.Configuration.TryGetNetworkFile():823 -TryGetNetworkFile(['http://update-master.ixsystems.com/updates/ix_crl.pem']): Read 1028 bytes total
[2018/10/29 19:55:07] (DEBUG) freenasOS.Configuration.TryGetNetworkFile():693 -TryGetNetworkFile(['http://update.ixsystems.com/FreeNAS/Validators/ValidateUpdate-pcBO6C.txt', 'http://update-master.ixsystems.com/FreeNAS/Validators/ValidateUpdate-pcBO6C.txt'])
[2018/10/29 19:55:07] (DEBUG) freenasOS.Configuration.CheckFreeSpace():84 - CheckFreeSpace(path=/tmp/tmp_502n_l0, pool=None, required=185)
[2018/10/29 19:55:07] (DEBUG) freenasOS.Configuration.TryGetNetworkFile():823 -TryGetNetworkFile(['http://update.ixsystems.com/FreeNAS/Validators/ValidateUpdate-pcBO6C.txt', 'http://update-master.ixsystems.com/FreeNAS/Validators/ValidateUpdate-pcBO6C.txt']): Read 185 bytes total
[2018/10/29 19:55:07] (DEBUG) freenasOS.Update.CheckForUpdates():868 - CheckForUpdate: diffs = {'Packages': [(<freenasOS.Package.Package object at 0x81a194eb8>, 'upgrade', <freenasOS.Package.Package object at 0x81a015588>), (<freenasOS.Package.Package object at 0x81a194fd0>, 'upgrade', <freenasOS.Package.Package object at 0x81a015400>), (<freenasOS.Package.Package object at 0x81a194908>, 'upgrade', <freenasOS.Package.Package object at 0x81a0e4cc0>), (<freenasOS.Package.Package object at 0x81a194b38>, 'upgrade', <freenasOS.Package.Package object at 0x81a05b828>), (<freenasOS.Package.Package object at 0x81a199710>, 'upgrade', <freenasOS.Package.Package object at 0x81a05b710>)], 'Reboot': True, 'Sequence': ('0a65b499a3580457a312814cb337db1d', 'd2f5bbb81785fcff78abaf7e4a32bb6e')}
[2018/10/29 19:55:07] (DEBUG) freenasOS.Configuration.TryGetNetworkFile():693 -TryGetNetworkFile(['http://update.ixsystems.com/FreeNAS/FreeNAS-11.2-STABLE/ChangeLog.txt', 'http://update-master.ixsystems.com/FreeNAS/FreeNAS-11.2-STABLE/ChangeLog.txt'])
[2018/10/29 19:55:08] (DEBUG) freenasOS.Configuration.TryGetNetworkFile():823 -TryGetNetworkFile(['http://update.ixsystems.com/FreeNAS/FreeNAS-11.2-STABLE/ChangeLog.txt', 'http://update-master.ixsystems.com/FreeNAS/FreeNAS-11.2-STABLE/ChangeLog.txt']): Read 49433 bytes total
[root@freenas ~]#

#7 Updated by Dru Lavigne over 1 year ago

  • Status changed from Passed Testing to Done
  • Needs Merging changed from Yes to No

Also available in: Atom PDF