aries-cloudagent-python: Error creating an auto provisioned Askar Postgres 15 database on startup using v0.8.1-rc2

The following error occurs when starting aca-py v0.8.1-rc2 set to auto provision a new Askar database. As a result aca-py is unable to start. Auto provisioning a indy database works without error.

2023-04-04 17:57:09,415 aries_cloudagent.core.plugin_registry DEBUG Loaded module: aries_cloudagent.protocols.actionmenu
2023-04-04 17:57:09,417 aries_cloudagent.core.plugin_registry DEBUG Loaded module: aries_cloudagent.protocols.basicmessage
2023-04-04 17:57:09,419 aries_cloudagent.core.plugin_registry DEBUG Loaded module: aries_cloudagent.protocols.connections
2023-04-04 17:57:09,420 aries_cloudagent.core.plugin_registry DEBUG Loaded module: aries_cloudagent.protocols.coordinate_mediation
2023-04-04 17:57:09,421 aries_cloudagent.core.plugin_registry DEBUG Loaded module: aries_cloudagent.protocols.didexchange
2023-04-04 17:57:09,422 aries_cloudagent.core.plugin_registry DEBUG Loaded module: aries_cloudagent.protocols.discovery
2023-04-04 17:57:09,424 aries_cloudagent.core.plugin_registry DEBUG Loaded module: aries_cloudagent.protocols.endorse_transaction
2023-04-04 17:57:09,425 aries_cloudagent.core.plugin_registry DEBUG Loaded module: aries_cloudagent.protocols.introduction
2023-04-04 17:57:09,426 aries_cloudagent.core.plugin_registry DEBUG Loaded module: aries_cloudagent.protocols.issue_credential
2023-04-04 17:57:09,428 aries_cloudagent.core.plugin_registry DEBUG Loaded module: aries_cloudagent.protocols.notification
2023-04-04 17:57:09,429 aries_cloudagent.core.plugin_registry DEBUG Loaded module: aries_cloudagent.protocols.out_of_band
2023-04-04 17:57:09,430 aries_cloudagent.core.plugin_registry DEBUG Loaded module: aries_cloudagent.protocols.present_proof
2023-04-04 17:57:09,431 aries_cloudagent.core.plugin_registry DEBUG Loaded module: aries_cloudagent.protocols.problem_report
2023-04-04 17:57:09,432 aries_cloudagent.core.plugin_registry DEBUG Loaded module: aries_cloudagent.protocols.revocation_notification
2023-04-04 17:57:09,435 aries_cloudagent.core.plugin_registry DEBUG Loaded module: aries_cloudagent.protocols.routing
2023-04-04 17:57:09,436 aries_cloudagent.core.plugin_registry DEBUG Loaded module: aries_cloudagent.protocols.trustping
2023-04-04 17:57:09,438 aries_cloudagent.core.plugin_registry DEBUG Loaded module: aries_cloudagent.holder
2023-04-04 17:57:09,449 aries_cloudagent.core.plugin_registry DEBUG Loaded module: aries_cloudagent.ledger
2023-04-04 17:57:09,486 aries_cloudagent.core.plugin_registry DEBUG Loaded module: aries_cloudagent.messaging.credential_definitions
2023-04-04 17:57:09,514 aries_cloudagent.core.plugin_registry DEBUG Loaded module: aries_cloudagent.messaging.schemas
2023-04-04 17:57:09,525 aries_cloudagent.core.plugin_registry DEBUG Loaded module: aries_cloudagent.messaging.jsonld
2023-04-04 17:57:09,534 aries_cloudagent.core.plugin_registry DEBUG Loaded module: aries_cloudagent.revocation
2023-04-04 17:57:09,569 aries_cloudagent.core.plugin_registry DEBUG Loaded module: aries_cloudagent.resolver
2023-04-04 17:57:09,569 aries_cloudagent.core.plugin_registry DEBUG Loaded module: aries_cloudagent.wallet
2023-04-04 17:57:09,591 aries_cloudagent.resolver WARNING Ledger is not configured, not loading IndyDIDResolver
2023-04-04 17:57:09,662 aries_cloudagent.core.event_bus DEBUG Subscribed: topic re.compile('^acapy::core::startup?$'), processor <function on_startup_event at 0x7f93047d3b80>
2023-04-04 17:57:09,662 aries_cloudagent.core.event_bus DEBUG Subscribed: topic re.compile('^acapy::core::shutdown?$'), processor <function on_shutdown_event at 0x7f93047d3c10>
2023-04-04 17:57:09,785 aries_cloudagent.core.event_bus DEBUG Subscribed: topic re.compile('^acapy::REVOCATION::published.*'), processor <function on_revocation_published at 0x7f9304625c10>
2023-04-04 17:57:09,786 aries_cloudagent.core.event_bus DEBUG Subscribed: topic re.compile('^acapy::REVOCATION::clear-pending.*'), processor <function on_pending_cleared at 0x7f93045d4160>
2023-04-04 17:57:09,791 aries_cloudagent.core.event_bus DEBUG Subscribed: topic re.compile('^acapy::REVOCATION::published.*'), processor <function on_revocation_published at 0x7f93045d4430>
2023-04-04 17:57:09,791 aries_cloudagent.core.event_bus DEBUG Subscribed: topic re.compile('^acapy::REVOCATION::clear-pending.*'), processor <function on_pending_cleared at 0x7f93045d4b80>
2023-04-04 17:57:09,795 aries_cloudagent.core.event_bus DEBUG Subscribed: topic re.compile('^acapy::CRED_DEF::(.*)?$'), processor <function on_cred_def_event at 0x7f9304a041f0>
2023-04-04 17:57:09,795 aries_cloudagent.core.event_bus DEBUG Subscribed: topic re.compile('^acapy::SCHEMA::(.*)?$'), processor <function on_schema_event at 0x7f9304a04b80>
2023-04-04 17:57:09,795 aries_cloudagent.core.event_bus DEBUG Subscribed: topic re.compile('^acapy::REVOCATION::REGISTRY_INIT.*'), processor <function on_revocation_registry_init_event at 0x7f930495c670>
2023-04-04 17:57:09,796 aries_cloudagent.core.event_bus DEBUG Subscribed: topic re.compile('^acapy::REVOCATION::REGISTRY_ENDORSED.*'), processor <function on_revocation_registry_endorsed_event at 0x7f930495cf70>
2023-04-04 17:57:09,796 aries_cloudagent.core.event_bus DEBUG Subscribed: topic re.compile('^acapy::REVOCATION::SEND_ENTRY.*'), processor <function on_revocation_entry_event at 0x7f930495c700>
2023-04-04 17:57:09,798 aries_cloudagent.core.event_bus DEBUG Subscribed: topic re.compile('^acapy::ENDORSE_DID::(.*)?$'), processor <function on_register_nym_event at 0x7f930491da60>
2023-04-04 17:57:09,798 aries_cloudagent.core.profile INFO Create profile manager: askar
2023-04-04 17:57:09,818 aries_askar.native.aries_askar.ffi.log DEBUG 	src/ffi/log.rs:123 | Initialized custom logger
2023-04-04 17:57:10,074 aries_askar.native.sqlx.query INFO 	None:0 | CREATE DATABASE "aries-mediator-agent-askar-wallet"; rows affected: 0, rows returned: 0, elapsed: 237.291ms
2023-04-04 17:57:10,083 aries_askar.native.sqlx.query DEBUG 	None:0 | BEGIN; rows affected: 0, rows returned: 0, elapsed: 270.321µs
2023-04-04 17:57:10,087 aries_askar.native.sqlx.query DEBUG 	None:0 | SELECT COUNT(*) FROM information_schema.tables …; rows affected: 0, rows returned: 1, elapsed: 3.190ms

SELECT
  COUNT(*)
FROM
  information_schema.tables
WHERE
  table_schema = 'public'
  AND table_name = 'config'

2023-04-04 17:57:11,763 aries_askar.native.sqlx.query DEBUG 	None:0 | CREATE TABLE config ( …; rows affected: 0, rows returned: 0, elapsed: 549.568µs

CREATE TABLE config (
  name TEXT NOT NULL,
  value TEXT,
  PRIMARY KEY(name)
);
CREATE TABLE profiles (
  id BIGSERIAL,
  name TEXT NOT NULL,
  reference TEXT NULL,
  profile_key BYTEA NULL,
  PRIMARY KEY(id)
);
CREATE UNIQUE INDEX ix_profile_name ON profiles(name);
CREATE TABLE items (
  id BIGSERIAL,
  profile_id BIGINT NOT NULL,
  kind SMALLINT NOT NULL,
  category BYTEA NOT NULL,
  name BYTEA NOT NULL,
  value BYTEA NOT NULL,
  expiry TIMESTAMP NULL,
  PRIMARY KEY(id),
  FOREIGN KEY(profile_id) REFERENCES profiles(id) ON DELETE CASCADE ON
  UPDATE
    CASCADE
);
CREATE UNIQUE INDEX ix_items_uniq ON items(profile_id, kind, category, name);
CREATE TABLE items_tags (
  id BIGSERIAL,
  item_id BIGINT NOT NULL,
  name BYTEA NOT NULL,
  value BYTEA NOT NULL,
  plaintext SMALLINT NOT NULL,
  PRIMARY KEY(id),
  FOREIGN KEY(item_id) REFERENCES items(id) ON DELETE CASCADE ON
  UPDATE
    CASCADE
);
CREATE INDEX ix_items_tags_item_id ON items_tags(item_id);
CREATE INDEX ix_items_tags_name_enc ON items_tags(name, SUBSTR(value, 1, 12)) include (item_id)
WHERE
  plaintext = 0;
CREATE INDEX ix_items_tags_name_plain ON items_tags(name, value) include (item_id)
WHERE
  plaintext = 1;

2023-04-04 17:57:11,768 aries_cloudagent.commands.start ERROR Exception during startup:
Traceback (most recent call last):
  File "/home/indy/.local/lib/python3.9/site-packages/aries_cloudagent/askar/store.py", line 150, in open_store
    store = await Store.provision(
  File "/home/indy/.local/lib/python3.9/site-packages/aries_askar/store.py", line 311, in provision
    await bindings.store_provision(
  File "/home/indy/.local/lib/python3.9/site-packages/aries_askar/bindings/__init__.py", line 102, in store_provision
    return await invoke_async(
  File "/home/indy/.local/lib/python3.9/site-packages/aries_askar/bindings/lib.py", line 358, in invoke_async
    return await self.loaded.invoke_async(
  File "/usr/local/lib/python3.9/asyncio/futures.py", line 284, in __await__
    yield self  # This tells Task to wait for completion.
  File "/usr/local/lib/python3.9/asyncio/tasks.py", line 328, in __wakeup
    future.result()
  File "/usr/local/lib/python3.9/asyncio/futures.py", line 201, in result
    raise self._exception
aries_askar.error.AskarError: Backend error
Caused by: error returned from database: syntax error at or near "include"

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

Traceback (most recent call last):
  File "/home/indy/.local/lib/python3.9/site-packages/aries_cloudagent/commands/start.py", line 72, in init
    await startup
  File "/home/indy/.local/lib/python3.9/site-packages/aries_cloudagent/commands/start.py", line 28, in start_app
    await conductor.setup()
  File "/home/indy/.local/lib/python3.9/site-packages/aries_cloudagent/core/conductor.py", line 134, in setup
    self.root_profile, self.setup_public_did = await wallet_config(context)
  File "/home/indy/.local/lib/python3.9/site-packages/aries_cloudagent/config/wallet.py", line 57, in wallet_config
    profile = await mgr.provision(context, profile_cfg)
  File "/home/indy/.local/lib/python3.9/site-packages/aries_cloudagent/askar/store.py", line 171, in open_store
    raise ProfileError("Error opening store") from err
aries_cloudagent.core.error.ProfileError: Error opening store

Shutting down
2023-04-04 17:57:11,778 aries_askar.native.aries_askar.ffi.log DEBUG 	src/ffi/log.rs:130 | Removing custom logger

Subsequent restarts experience the following error:

2023-04-04 17:57:15,091 aries_cloudagent.core.plugin_registry DEBUG Loaded module: aries_cloudagent.protocols.actionmenu
2023-04-04 17:57:15,094 aries_cloudagent.core.plugin_registry DEBUG Loaded module: aries_cloudagent.protocols.basicmessage
2023-04-04 17:57:15,095 aries_cloudagent.core.plugin_registry DEBUG Loaded module: aries_cloudagent.protocols.connections
2023-04-04 17:57:15,096 aries_cloudagent.core.plugin_registry DEBUG Loaded module: aries_cloudagent.protocols.coordinate_mediation
2023-04-04 17:57:15,097 aries_cloudagent.core.plugin_registry DEBUG Loaded module: aries_cloudagent.protocols.didexchange
2023-04-04 17:57:15,098 aries_cloudagent.core.plugin_registry DEBUG Loaded module: aries_cloudagent.protocols.discovery
2023-04-04 17:57:15,101 aries_cloudagent.core.plugin_registry DEBUG Loaded module: aries_cloudagent.protocols.endorse_transaction
2023-04-04 17:57:15,103 aries_cloudagent.core.plugin_registry DEBUG Loaded module: aries_cloudagent.protocols.introduction
2023-04-04 17:57:15,104 aries_cloudagent.core.plugin_registry DEBUG Loaded module: aries_cloudagent.protocols.issue_credential
2023-04-04 17:57:15,105 aries_cloudagent.core.plugin_registry DEBUG Loaded module: aries_cloudagent.protocols.notification
2023-04-04 17:57:15,107 aries_cloudagent.core.plugin_registry DEBUG Loaded module: aries_cloudagent.protocols.out_of_band
2023-04-04 17:57:15,108 aries_cloudagent.core.plugin_registry DEBUG Loaded module: aries_cloudagent.protocols.present_proof
2023-04-04 17:57:15,109 aries_cloudagent.core.plugin_registry DEBUG Loaded module: aries_cloudagent.protocols.problem_report
2023-04-04 17:57:15,110 aries_cloudagent.core.plugin_registry DEBUG Loaded module: aries_cloudagent.protocols.revocation_notification
2023-04-04 17:57:15,113 aries_cloudagent.core.plugin_registry DEBUG Loaded module: aries_cloudagent.protocols.routing
2023-04-04 17:57:15,115 aries_cloudagent.core.plugin_registry DEBUG Loaded module: aries_cloudagent.protocols.trustping
2023-04-04 17:57:15,118 aries_cloudagent.core.plugin_registry DEBUG Loaded module: aries_cloudagent.holder
2023-04-04 17:57:15,132 aries_cloudagent.core.plugin_registry DEBUG Loaded module: aries_cloudagent.ledger
2023-04-04 17:57:15,163 aries_cloudagent.core.plugin_registry DEBUG Loaded module: aries_cloudagent.messaging.credential_definitions
2023-04-04 17:57:15,187 aries_cloudagent.core.plugin_registry DEBUG Loaded module: aries_cloudagent.messaging.schemas
2023-04-04 17:57:15,196 aries_cloudagent.core.plugin_registry DEBUG Loaded module: aries_cloudagent.messaging.jsonld
2023-04-04 17:57:15,202 aries_cloudagent.core.plugin_registry DEBUG Loaded module: aries_cloudagent.revocation
2023-04-04 17:57:15,227 aries_cloudagent.core.plugin_registry DEBUG Loaded module: aries_cloudagent.resolver
2023-04-04 17:57:15,227 aries_cloudagent.core.plugin_registry DEBUG Loaded module: aries_cloudagent.wallet
2023-04-04 17:57:15,249 aries_cloudagent.resolver WARNING Ledger is not configured, not loading IndyDIDResolver
2023-04-04 17:57:15,327 aries_cloudagent.core.event_bus DEBUG Subscribed: topic re.compile('^acapy::core::startup?$'), processor <function on_startup_event at 0x7f0222faeb80>
2023-04-04 17:57:15,327 aries_cloudagent.core.event_bus DEBUG Subscribed: topic re.compile('^acapy::core::shutdown?$'), processor <function on_shutdown_event at 0x7f0222faec10>
2023-04-04 17:57:15,458 aries_cloudagent.core.event_bus DEBUG Subscribed: topic re.compile('^acapy::REVOCATION::published.*'), processor <function on_revocation_published at 0x7f0222e00c10>
2023-04-04 17:57:15,458 aries_cloudagent.core.event_bus DEBUG Subscribed: topic re.compile('^acapy::REVOCATION::clear-pending.*'), processor <function on_pending_cleared at 0x7f0222daf160>
2023-04-04 17:57:15,463 aries_cloudagent.core.event_bus DEBUG Subscribed: topic re.compile('^acapy::REVOCATION::published.*'), processor <function on_revocation_published at 0x7f0222daf430>
2023-04-04 17:57:15,463 aries_cloudagent.core.event_bus DEBUG Subscribed: topic re.compile('^acapy::REVOCATION::clear-pending.*'), processor <function on_pending_cleared at 0x7f0222dafb80>
2023-04-04 17:57:15,467 aries_cloudagent.core.event_bus DEBUG Subscribed: topic re.compile('^acapy::CRED_DEF::(.*)?$'), processor <function on_cred_def_event at 0x7f02231df1f0>
2023-04-04 17:57:15,467 aries_cloudagent.core.event_bus DEBUG Subscribed: topic re.compile('^acapy::SCHEMA::(.*)?$'), processor <function on_schema_event at 0x7f02231dfb80>
2023-04-04 17:57:15,468 aries_cloudagent.core.event_bus DEBUG Subscribed: topic re.compile('^acapy::REVOCATION::REGISTRY_INIT.*'), processor <function on_revocation_registry_init_event at 0x7f0223137670>
2023-04-04 17:57:15,468 aries_cloudagent.core.event_bus DEBUG Subscribed: topic re.compile('^acapy::REVOCATION::REGISTRY_ENDORSED.*'), processor <function on_revocation_registry_endorsed_event at 0x7f0223137f70>
2023-04-04 17:57:15,468 aries_cloudagent.core.event_bus DEBUG Subscribed: topic re.compile('^acapy::REVOCATION::SEND_ENTRY.*'), processor <function on_revocation_entry_event at 0x7f0223137700>
2023-04-04 17:57:15,470 aries_cloudagent.core.event_bus DEBUG Subscribed: topic re.compile('^acapy::ENDORSE_DID::(.*)?$'), processor <function on_register_nym_event at 0x7f02230f8a60>
2023-04-04 17:57:15,471 aries_cloudagent.core.profile INFO Create profile manager: askar
2023-04-04 17:57:15,494 aries_askar.native.aries_askar.ffi.log DEBUG 	src/ffi/log.rs:123 | Initialized custom logger
2023-04-04 17:57:15,507 aries_askar.native.sqlx.query DEBUG 	None:0 | SELECT name, value FROM …; rows affected: 0, rows returned: 0, elapsed: 588.385µs

SELECT
  name,
  value
FROM
  config
WHERE
  name IN ('default_profile', 'key', 'version')

2023-04-04 17:57:15,508 aries_cloudagent.commands.start ERROR Exception during startup:
Traceback (most recent call last):
  File "/home/indy/.local/lib/python3.9/site-packages/aries_cloudagent/askar/store.py", line 157, in open_store
    store = await Store.open(
  File "/home/indy/.local/lib/python3.9/site-packages/aries_askar/store.py", line 326, in open
    return Store(await bindings.store_open(uri, key_method, pass_key, profile), uri)
  File "/home/indy/.local/lib/python3.9/site-packages/aries_askar/bindings/__init__.py", line 83, in store_open
    return await invoke_async(
  File "/home/indy/.local/lib/python3.9/site-packages/aries_askar/bindings/lib.py", line 358, in invoke_async
    return await self.loaded.invoke_async(
  File "/usr/local/lib/python3.9/asyncio/futures.py", line 284, in __await__
    yield self  # This tells Task to wait for completion.
  File "/usr/local/lib/python3.9/asyncio/tasks.py", line 328, in __wakeup
    future.result()
  File "/usr/local/lib/python3.9/asyncio/futures.py", line 201, in result
    raise self._exception
aries_askar.error.AskarError: Backend error
Caused by: error returned from database: relation "config" does not exist

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

Traceback (most recent call last):
  File "/home/indy/.local/lib/python3.9/site-packages/aries_cloudagent/commands/start.py", line 72, in init
    await startup
  File "/home/indy/.local/lib/python3.9/site-packages/aries_cloudagent/commands/start.py", line 28, in start_app
    await conductor.setup()
  File "/home/indy/.local/lib/python3.9/site-packages/aries_cloudagent/core/conductor.py", line 134, in setup
    self.root_profile, self.setup_public_did = await wallet_config(context)
  File "/home/indy/.local/lib/python3.9/site-packages/aries_cloudagent/config/wallet.py", line 54, in wallet_config
    profile = await mgr.open(context, profile_cfg)
  File "/home/indy/.local/lib/python3.9/site-packages/aries_cloudagent/askar/profile.py", line 261, in open
    opened = await store_config.open_store(provision=False)
  File "/home/indy/.local/lib/python3.9/site-packages/aries_cloudagent/askar/store.py", line 171, in open_store
    raise ProfileError("Error opening store") from err
aries_cloudagent.core.error.ProfileError: Error opening store

Shutting down
2023-04-04 17:57:15,512 aries_askar.native.aries_askar.ffi.log DEBUG 	src/ffi/log.rs:130 | Removing custom logger