sqlite3 error on middleware start: no such column: system_settings.stg_birthday

Description

After upgrading from freenas 11.3U(4?) to TrueNas 12.0 Release I'm having issues with middleware crashing on startup, causing nothing to work.

Seems to be a missing column in system_settings, stg_birthday (system_settings.stg_birthday)

Logs below:

[2020/10/29 00:45:14] (INFO) middlewared._init_():792 - Starting TrueNAS-12.0-RELEASE middleware
[2020/10/29 00:45:17] (ERROR) asyncio.default_exception_handler():1707 - Task exception was never retrieved
future: <Task finished name='Task-1' coro=<Middleware.__initialize() done, defined at /usr/local/lib/python3.8/site-packages/middlewared/main.py:1434> exception=OperationalError('(sqlite3.OperationalError) no such column: system_settings.stg_birthday')>
Traceback (most recent call last):
File "/usr/local/lib/python3.8/site-packages/sqlalchemy/engine/base.py", line 1247, in _execute_context
self.dialect.do_execute(
File "/usr/local/lib/python3.8/site-packages/sqlalchemy/engine/default.py", line 590, in do_execute
cursor.execute(statement, parameters)
sqlite3.OperationalError: no such column: system_settings.stg_birthday

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

Traceback (most recent call last):
File "/usr/local/lib/python3.8/site-packages/middlewared/main.py", line 1480, in __initialize
await self.__plugins_setup(setup_funcs)
File "/usr/local/lib/python3.8/site-packages/middlewared/main.py", line 901, in __plugins_setup
await call
File "/usr/local/lib/python3.8/site-packages/middlewared/plugins/pwenc.py", line 80, in setup
if not await middleware.call('pwenc.check'):
File "/usr/local/lib/python3.8/site-packages/middlewared/main.py", line 1233, in call
return await self._call(
File "/usr/local/lib/python3.8/site-packages/middlewared/main.py", line 1202, in _call
return await self.run_in_executor(prepared_call.executor, methodobj, *prepared_call.args)
File "/usr/local/lib/python3.8/site-packages/middlewared/main.py", line 1106, in run_in_executor
return await loop.run_in_executor(pool, functools.partial(method, *args, **kwargs))
File "/usr/local/lib/python3.8/site-packages/middlewared/utils/io_thread_pool_executor.py", line 25, in run
result = self.fn(*self.args, **self.kwargs)
File "/usr/local/lib/python3.8/site-packages/middlewared/plugins/pwenc.py", line 51, in check
settings = self.middleware.call_sync('datastore.config', 'system.settings')
File "/usr/local/lib/python3.8/site-packages/middlewared/main.py", line 1249, in call_sync
return self.run_coroutine(methodobj(*prepared_call.args))
File "/usr/local/lib/python3.8/site-packages/middlewared/main.py", line 1289, in run_coroutine
return fut.result()
File "/usr/local/lib/python3.8/concurrent/futures/_base.py", line 432, in result
return self.__get_result()
File "/usr/local/lib/python3.8/concurrent/futures/_base.py", line 388, in __get_result
raise self._exception
File "/usr/local/lib/python3.8/site-packages/middlewared/schema.py", line 973, in nf
return await f(*args, **kwargs)
File "/usr/local/lib/python3.8/site-packages/middlewared/plugins/datastore/read.py", line 185, in config
return await self.query(name, [], options)
File "/usr/local/lib/python3.8/site-packages/middlewared/schema.py", line 973, in nf
return await f(*args, **kwargs)
File "/usr/local/lib/python3.8/site-packages/middlewared/plugins/datastore/read.py", line 156, in query
result = await self.middleware.call("datastore.fetchall", qs)
File "/usr/local/lib/python3.8/site-packages/middlewared/main.py", line 1233, in call
return await self._call(
File "/usr/local/lib/python3.8/site-packages/middlewared/main.py", line 1191, in _call
return await methodobj(*prepared_call.args)
File "/usr/local/lib/python3.8/site-packages/middlewared/plugins/datastore/connection.py", line 74, in fetchall
return await self.middleware.run_in_executor(self.thread_pool, self._fetchall, *args)
File "/usr/local/lib/python3.8/site-packages/middlewared/main.py", line 1106, in run_in_executor
return await loop.run_in_executor(pool, functools.partial(method, *args, **kwargs))
File "/usr/local/lib/python3.8/concurrent/futures/thread.py", line 57, in run
result = self.fn(*self.args, **self.kwargs)
File "/usr/local/lib/python3.8/site-packages/middlewared/plugins/datastore/connection.py", line 77, in _fetchall
cursor = self.connection.execute(query, params or [])
File "/usr/local/lib/python3.8/site-packages/sqlalchemy/engine/base.py", line 984, in execute
return meth(self, multiparams, params)
File "/usr/local/lib/python3.8/site-packages/sqlalchemy/sql/elements.py", line 293, in _execute_on_connection
return connection._execute_clauseelement(self, multiparams, params)
File "/usr/local/lib/python3.8/site-packages/sqlalchemy/engine/base.py", line 1097, in _execute_clauseelement
ret = self._execute_context(
File "/usr/local/lib/python3.8/site-packages/sqlalchemy/engine/base.py", line 1287, in _execute_context
self._handle_dbapi_exception(
File "/usr/local/lib/python3.8/site-packages/sqlalchemy/engine/base.py", line 1481, in _handle_dbapi_exception
util.raise_(
File "/usr/local/lib/python3.8/site-packages/sqlalchemy/util/compat.py", line 178, in raise_
raise exception
File "/usr/local/lib/python3.8/site-packages/sqlalchemy/engine/base.py", line 1247, in _execute_context
self.dialect.do_execute(
File "/usr/local/lib/python3.8/site-packages/sqlalchemy/engine/default.py", line 590, in do_execute
cursor.execute(statement, parameters)
sqlalchemy.exc.OperationalError: (sqlite3.OperationalError) no such column: system_settings.stg_birthday
[SQL: SELECT system_settings.id, system_settings.stg_guiaddress, system_settings.stg_guiv6address, system_settings.stg_guiport, system_settings.stg_guihttpsport, system_settings.stg_guihttpsredirect, system_settings.stg_language, system_settings.stg_kbdmap, system_settings.stg_birthday, system_settings.stg_timezone, system_settings.stg_wizardshown, system_settings.stg_pwenc_check, system_settings.stg_guicertificate_id, system_settings.stg_crash_reporting, system_settings.stg_usage_collection, system_settings.stg_guihttpsprotocols, system_certificate_1.id, system_certificate_1.cert_type, system_certificate_1.cert_name, system_certificate_1.cert_certificate, system_certificate_1.cert_privatekey, system_certificate_1."cert_CSR", system_certificate_1.cert_signedby_id, system_certificate_1.cert_acme_uri, system_certificate_1.cert_domains_authenticators, system_certificate_1.cert_renew_days, system_certificate_1.cert_acme_id, system_certificate_1.cert_revoked_date, system_certificateauthority_1.id, system_certificateauthority_1.cert_type, system_certificateauthority_1.cert_name, system_certificateauthority_1.cert_certificate, system_certificateauthority_1.cert_privatekey, system_certificateauthority_1."cert_CSR", system_certificateauthority_1.cert_revoked_date, system_certificateauthority_1.cert_signedby_id, system_certificateauthority_2.id, system_certificateauthority_2.cert_type, system_certificateauthority_2.cert_name, system_certificateauthority_2.cert_certificate, system_certificateauthority_2.cert_privatekey, system_certificateauthority_2."cert_CSR", system_certificateauthority_2.cert_revoked_date, system_certificateauthority_2.cert_signedby_id, system_acmeregistration_1.id, system_acmeregistration_1.uri, system_acmeregistration_1.directory, system_acmeregistration_1.tos, system_acmeregistration_1.new_account_uri, system_acmeregistration_1.new_nonce_uri, system_acmeregistration_1.new_order_uri, system_acmeregistration_1.revoke_cert_uri
FROM system_settings LEFT OUTER JOIN system_certificate AS system_certificate_1 ON system_certificate_1.id = system_settings.stg_guicertificate_id LEFT OUTER JOIN system_certificateauthority AS system_certificateauthority_1 ON system_certificateauthority_1.id = system_certificate_1.cert_signedby_id LEFT OUTER JOIN system_certificateauthority AS system_certificateauthority_2 ON system_certificateauthority_2.id = system_certificateauthority_1.cert_signedby_id LEFT OUTER JOIN system_acmeregistration AS system_acmeregistration_1 ON system_acmeregistration_1.id = system_certificate_1.cert_acme_id]
(Background on this error at: http://sqlalche.me/e/e3q8)

Also getting an error on middleware termination but that may simply be caused by startup failing:

[2020/10/29 00:45:13] (INFO) middlewared.terminate():1494 - Terminating
[2020/10/29 00:45:13] (ERROR) middlewared.__terminate():1518 - Failed to terminate alert
Traceback (most recent call last):
File "/usr/local/lib/python3.8/site-packages/middlewared/main.py", line 1516, in __terminate
await asyncio.wait_for(service.terminate(), timeout)
File "/usr/local/lib/python3.8/asyncio/tasks.py", line 483, in wait_for
return fut.result()
File "/usr/local/lib/python3.8/site-packages/middlewared/plugins/alert.py", line 237, in terminate
await self.flush_alerts()
File "/usr/local/lib/python3.8/site-packages/middlewared/plugins/alert.py", line 748, in flush_alerts
for alert in self.alerts:
AttributeError: 'AlertService' object has no attribute 'alerts'

Problem/Justification

None

Impact

None

SmartDraw Connector

Katalon Manual Tests (BETA)

Activity

Fredrik

November 9, 2020 at 6:41 PM

Indeed it does, this ticket can be closed

Vladimir Vinogradenko

November 9, 2020 at 6:26 PM

@Fredrik after a reboot your system should function normally

Fredrik

November 9, 2020 at 5:45 PM

That seems to have done the trick, web ui is now working. Output below

root@truenas:~ # migrate
+ python3 -c 'import os; import middlewared; print(os.path.dirname(middlewared.__spec__.origin))'
+ cd /usr/local/lib/python3.8/site-packages/middlewared
+ alembic upgrade head
INFO  [alembic.runtime.migration] Context impl SQLiteImpl.
INFO  [alembic.runtime.migration] Will assume non-transactional DDL.
INFO  [alembic.runtime.migration] Running upgrade 133f2d9049d2 -> 39a133a04496, empty message
INFO  [alembic.runtime.migration] Running upgrade 39a133a04496 -> f3875acb8d76, Fix user shell choices
INFO  [alembic.runtime.migration] Running upgrade f3875acb8d76 -> 536cbfca20e6, Drop iSCSI initiator tag column
INFO  [alembic.runtime.migration] Running upgrade 536cbfca20e6 -> bc290fddc888, Simplify SMB shares
INFO  [alembic.runtime.migration] Running upgrade bc290fddc888 -> f6a18dec20fa, Simplify and clean up idmap backends
INFO  [alembic.runtime.migration] Running upgrade f6a18dec20fa -> 4abbf75347b2, Add SMB flag to users and groups
INFO  [alembic.runtime.migration] Running upgrade 4abbf75347b2 -> 06bfbd354deb, SSH weak ciphers
INFO  [alembic.runtime.migration] Running upgrade 06bfbd354deb -> b5cac06345ea, webdav_enable
INFO  [alembic.runtime.migration] Running upgrade b5cac06345ea -> 8f874e6e40bc, Replication readonly
INFO  [alembic.runtime.migration] Running upgrade 8f874e6e40bc -> 32f55c715352, Add ad_restrict_pam key
INFO  [alembic.runtime.migration] Running upgrade 32f55c715352 -> a06b1946f6a3, empty message
INFO  [alembic.runtime.migration] Running upgrade a06b1946f6a3 -> 6602857581db, API Key
INFO  [alembic.runtime.migration] Running upgrade 6602857581db -> 38773ca83199, API Key created_at
INFO  [alembic.runtime.migration] Running upgrade 38773ca83199 -> 29e866803c47, Overprovision
INFO  [alembic.runtime.migration] Running upgrade 29e866803c47 -> 171f5b91c36e, Fix replication foreign keys
INFO  [alembic.runtime.migration] Running upgrade 171f5b91c36e -> 58339783792c, TrueCommand Service Model
INFO  [alembic.runtime.migration] Running upgrade 58339783792c -> 83dae64197f3, Remove asigra table
INFO  [alembic.runtime.migration] Running upgrade 83dae64197f3 -> 2ab85192c49f, Encrypt SSH and certificates private keys
INFO  [alembic.runtime.migration] Running upgrade 2ab85192c49f -> 43779dce3a07, Convert SMB bindip not null
INFO  [alembic.runtime.migration] Running upgrade 43779dce3a07 -> 22230265ab30, iSCSI Vendor configuration
INFO  [alembic.runtime.migration] Running upgrade 22230265ab30 -> 434ea5397cd3, encrypt smbhash
INFO  [alembic.runtime.migration] Running upgrade 434ea5397cd3 -> 730c995cbd37, remove nmbclusters sysctl
INFO  [alembic.runtime.migration] Running upgrade 730c995cbd37 -> e9e611d7c5a7, make netatalk logging configurable
INFO  [alembic.runtime.migration] Running upgrade e9e611d7c5a7 -> a3ac49efb063, birthday
INFO  [alembic.runtime.migration] Running upgrade a3ac49efb063 -> b694f05c1169, Run data migration on install / factory reset
INFO  [alembic.runtime.migration] Running upgrade b694f05c1169 -> 1432b666093e, Remove replication dedup
INFO  [alembic.runtime.migration] Running upgrade 1432b666093e -> ffcd02f6af9f, Remove alerts unique index
INFO  [alembic.runtime.migration] Running upgrade ffcd02f6af9f -> 85346ccd33c0, Remove legacy freenas sysctls
INFO  [alembic.runtime.migration] Running upgrade 85346ccd33c0 -> 5a365c7248da, Add next_rid column to services_cifs
INFO  [alembic.runtime.migration] Running upgrade 5a365c7248da -> 8ac8158773c4, storage_disk primary key
INFO  [alembic.runtime.migration] Running upgrade 8ac8158773c4 -> c01e9d77922e, Add SMB secrets
INFO  [alembic.runtime.migration] Running upgrade c01e9d77922e -> 71a8d1e504a7, Add Rsyncmod enabled field
INFO  [alembic.runtime.migration] Running upgrade 71a8d1e504a7 -> 25962b409a1e, cleanup AD parameters
INFO  [alembic.runtime.migration] Running upgrade 25962b409a1e -> 6d3efdc7ba5b, Fix migrations state
INFO  [alembic.runtime.migration] Running upgrade 6d3efdc7ba5b -> 28ecea8be3fb, Make sure builtin users are not smb users
INFO  [alembic.runtime.migration] Running upgrade 28ecea8be3fb -> a3298f120609, Disk ZFS GUID

Vladimir Vinogradenko

November 9, 2020 at 2:58 PM

@Fredrik can you please run migrate and show us what it will print?

Fredrik

November 6, 2020 at 7:38 PM

Yes, its the full file

Resize work item view side panel

Cannot Reproduce

Details

Assignee

Triage Team

Reporter

Fredrik

Priority

Low

More fields

Katalon Platform

Created October 29, 2020 at 12:58 AM

Updated July 1, 2022 at 5:00 PM

Resolved November 9, 2020 at 6:58 PM

sqlite3 error on middleware start: no such column: system_settings.stg_birthday

Description

Problem/Justification

Impact

SmartDraw Connector

Katalon Manual Tests (BETA)

Activity

Details

Assignee

Reporter

Labels

Components

Fix versions

Affects versions

Priority

More fields

Katalon Platform