search

openwallet-foundation / acapy

Hyperledger Aries Cloud Agent Python (ACA-Py) is a foundation for building decentralized identity applications and services running in non-mobile environments.
https://wiki.hyperledger.org/display/aries
Apache License 2.0
412 stars 512 forks source link

Error creating an auto provisioned Askar Postgres 15 database on startup using v0.8.1-rc2 #2199

Closed WadeBarnes closed 10 months ago

WadeBarnes commented 1 year ago

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
WadeBarnes commented 1 year ago

To confirm, this was with a Postgres database. Version is 10.17 which is rather old. I'll look at updating.

andrewwhitehead commented 1 year ago

This change was added in Askar 0.2.8 (https://github.com/hyperledger/aries-askar/pull/57), so it could be pinned to 0.2.7 for compatibility with older Postgres versions (pre-11).

WadeBarnes commented 1 year ago

Good to know. Not sure we want to support older databases, but it would be good to note the breaking change. Version 10 is not being supported any longer.

swcurran commented 1 year ago

Wade — could you please provide some text for me to put into the CHANGELOG.md about this? What is useful to include?

What is the solution for us on this? New deployments must use new databases? And when we upgrade instances to Askar, we also have to upgrade Postgres versions?

WadeBarnes commented 1 year ago

Breaking change, Askar 0.2.8 no longer supports Postgres versions older than 11. If you are planning on deploying this new version, please ensure your Postgres version is 11 or newer.

shaangill025 commented 1 year ago

I was able to replicate the error even on Postgres:14. But with following approach [from Ian's test script], even Postgres:10 is working, if we standup storage on similar lines as below:

version: "3"
services:
  wallet-db:
    build: ./db
    environment:
      - POSTGRES_USER=DB_USER
      - POSTGRES_PASSWORD=DB_PASSWORD
      - POSTGRES_ADMIN_USER=postgres
      - POSTGRES_ADMIN_PASSWORD=mysecretpassword
    networks:
      - wallet-net
    ports:
      - 5432:5432
    volumes:
      - wallet-db-data:/var/lib/pgsql/data

volumes:
  wallet-db-data:

networks:
  wallet-net:

In /db

Dockerfile

FROM postgres:14
COPY ./init-postgres-role.sh /docker-entrypoint-initdb.d/init-postgres-role.sh
CMD ["docker-entrypoint.sh", "postgres"]
init-postgres-role.sh

#!/bin/bash
set -e

psql -v ON_ERROR_STOP=1 --username "$POSTGRES_USER" --dbname "$POSTGRES_DB" --set username=$POSTGRES_ADMIN_USER --set password="'$POSTGRES_ADMIN_PASSWORD'"<<-EOSQL
    CREATE ROLE :username WITH LOGIN SUPERUSER INHERIT CREATEDB CREATEROLE REPLICATION ENCRYPTED PASSWORD :password;
EOSQL
shaangill025 commented 1 year ago

I am getting that error if I use the following:

version: '3'
services:
  storage-db:
    image: postgres:14
    environment:
      - POSTGRES_USER=DB_USER
      - POSTGRES_PASSWORD=DB_PASSWORD
      - POSTGRES_ADMIN_USER=postgres
      - POSTGRES_ADMIN_PASSWORD=mysecretpassword
    ports:
      - "5432:5432"
    volumes:
      - storage-db-data:/var/lib/pgsql/data
    networks:
      - wallet-net
volumes:
  storage-db-data:
networks:
  wallet-net:
WadeBarnes commented 1 year ago

What is the solution for us on this? New deployments must use new databases? And when we upgrade instances to Askar, we also have to upgrade Postgres versions?

Solution for us is to upgrade our versions of Postgres. I did not realize the mediator was using an older version of Postgres. We are using a redhat version of Postgres 13 for other services.

shaangill025 commented 1 year ago

FYI, one scenario for int test [PR#2342] is failing with similar error. I believe these tests are setup with postgres:12.

swcurran commented 1 year ago

@shaangill025 — are you getting the same error on your tests with Postgres 14 or is it a different error? Its troublesome if that is the case and we need to understand more. I ran it on 15 and it ran fine.

shaangill025 commented 1 year ago

@swcurran I was pointing to the wrong service in wallet-storage-config in my test. Also, when using dockerfile: docker/Dockerfile.run to build [with main branch] instead of image: bcgovimages/aries-cloudagent:py36-1.16-1_0.8.1-rc2 then even postgres:10 worked which caused confusion on my end.

I have found that the minimum postgres version required for ACA-Py with Askar 0.2.8 to start up is 11 [image: postgres:11].

swcurran commented 1 year ago

Sounds good — thanks. So it all makes sense. Good stuff.

WadeBarnes commented 1 year ago

Getting the following error on startup with aca-py when it goes to create a new wallet database in OCP targeting a Postgres v15.1 database:

2023-04-05 17:09:03,909 aries_cloudagent.core.plugin_registry DEBUG Loaded module: aries_cloudagent.protocols.actionmenu
2023-04-05 17:09:03,910 aries_cloudagent.core.plugin_registry DEBUG Loaded module: aries_cloudagent.protocols.basicmessage
2023-04-05 17:09:03,911 aries_cloudagent.core.plugin_registry DEBUG Loaded module: aries_cloudagent.protocols.connections
2023-04-05 17:09:03,912 aries_cloudagent.core.plugin_registry DEBUG Loaded module: aries_cloudagent.protocols.coordinate_mediation
2023-04-05 17:09:03,913 aries_cloudagent.core.plugin_registry DEBUG Loaded module: aries_cloudagent.protocols.didexchange
2023-04-05 17:09:03,914 aries_cloudagent.core.plugin_registry DEBUG Loaded module: aries_cloudagent.protocols.discovery
2023-04-05 17:09:03,916 aries_cloudagent.core.plugin_registry DEBUG Loaded module: aries_cloudagent.protocols.endorse_transaction
2023-04-05 17:09:03,917 aries_cloudagent.core.plugin_registry DEBUG Loaded module: aries_cloudagent.protocols.introduction
2023-04-05 17:09:03,918 aries_cloudagent.core.plugin_registry DEBUG Loaded module: aries_cloudagent.protocols.issue_credential
2023-04-05 17:09:03,919 aries_cloudagent.core.plugin_registry DEBUG Loaded module: aries_cloudagent.protocols.notification
2023-04-05 17:09:03,920 aries_cloudagent.core.plugin_registry DEBUG Loaded module: aries_cloudagent.protocols.out_of_band
2023-04-05 17:09:03,921 aries_cloudagent.core.plugin_registry DEBUG Loaded module: aries_cloudagent.protocols.present_proof
2023-04-05 17:09:03,921 aries_cloudagent.core.plugin_registry DEBUG Loaded module: aries_cloudagent.protocols.problem_report
2023-04-05 17:09:03,922 aries_cloudagent.core.plugin_registry DEBUG Loaded module: aries_cloudagent.protocols.revocation_notification
2023-04-05 17:09:03,924 aries_cloudagent.core.plugin_registry DEBUG Loaded module: aries_cloudagent.protocols.routing
2023-04-05 17:09:03,925 aries_cloudagent.core.plugin_registry DEBUG Loaded module: aries_cloudagent.protocols.trustping
2023-04-05 17:09:03,927 aries_cloudagent.core.plugin_registry DEBUG Loaded module: aries_cloudagent.holder
2023-04-05 17:09:03,938 aries_cloudagent.core.plugin_registry DEBUG Loaded module: aries_cloudagent.ledger
2023-04-05 17:09:03,967 aries_cloudagent.core.plugin_registry DEBUG Loaded module: aries_cloudagent.messaging.credential_definitions
2023-04-05 17:09:03,985 aries_cloudagent.core.plugin_registry DEBUG Loaded module: aries_cloudagent.messaging.schemas
2023-04-05 17:09:03,995 aries_cloudagent.core.plugin_registry DEBUG Loaded module: aries_cloudagent.messaging.jsonld
2023-04-05 17:09:04,001 aries_cloudagent.core.plugin_registry DEBUG Loaded module: aries_cloudagent.revocation
2023-04-05 17:09:04,026 aries_cloudagent.core.plugin_registry DEBUG Loaded module: aries_cloudagent.resolver
2023-04-05 17:09:04,027 aries_cloudagent.core.plugin_registry DEBUG Loaded module: aries_cloudagent.wallet
2023-04-05 17:09:04,047 aries_cloudagent.resolver WARNING Ledger is not configured, not loading IndyDIDResolver
2023-04-05 17:09:04,117 aries_cloudagent.core.event_bus DEBUG Subscribed: topic re.compile('^acapy::core::startup?$'), processor <function on_startup_event at 0x7fe812992b80>
2023-04-05 17:09:04,118 aries_cloudagent.core.event_bus DEBUG Subscribed: topic re.compile('^acapy::core::shutdown?$'), processor <function on_shutdown_event at 0x7fe812992c10>
2023-04-05 17:09:04,236 aries_cloudagent.core.event_bus DEBUG Subscribed: topic re.compile('^acapy::REVOCATION::published.*'), processor <function on_revocation_published at 0x7fe8127e4c10>
2023-04-05 17:09:04,237 aries_cloudagent.core.event_bus DEBUG Subscribed: topic re.compile('^acapy::REVOCATION::clear-pending.*'), processor <function on_pending_cleared at 0x7fe812793160>
2023-04-05 17:09:04,241 aries_cloudagent.core.event_bus DEBUG Subscribed: topic re.compile('^acapy::REVOCATION::published.*'), processor <function on_revocation_published at 0x7fe812793430>
2023-04-05 17:09:04,242 aries_cloudagent.core.event_bus DEBUG Subscribed: topic re.compile('^acapy::REVOCATION::clear-pending.*'), processor <function on_pending_cleared at 0x7fe812793b80>
2023-04-05 17:09:04,247 aries_cloudagent.core.event_bus DEBUG Subscribed: topic re.compile('^acapy::CRED_DEF::(.*)?$'), processor <function on_cred_def_event at 0x7fe812bc31f0>
2023-04-05 17:09:04,247 aries_cloudagent.core.event_bus DEBUG Subscribed: topic re.compile('^acapy::SCHEMA::(.*)?$'), processor <function on_schema_event at 0x7fe812bc3b80>
2023-04-05 17:09:04,248 aries_cloudagent.core.event_bus DEBUG Subscribed: topic re.compile('^acapy::REVOCATION::REGISTRY_INIT.*'), processor <function on_revocation_registry_init_event at 0x7fe812b1b670>
2023-04-05 17:09:04,248 aries_cloudagent.core.event_bus DEBUG Subscribed: topic re.compile('^acapy::REVOCATION::REGISTRY_ENDORSED.*'), processor <function on_revocation_registry_endorsed_event at 0x7fe812b1bf70>
2023-04-05 17:09:04,249 aries_cloudagent.core.event_bus DEBUG Subscribed: topic re.compile('^acapy::REVOCATION::SEND_ENTRY.*'), processor <function on_revocation_entry_event at 0x7fe812b1b700>
2023-04-05 17:09:04,251 aries_cloudagent.core.event_bus DEBUG Subscribed: topic re.compile('^acapy::ENDORSE_DID::(.*)?$'), processor <function on_register_nym_event at 0x7fe812adca60>
2023-04-05 17:09:04,251 aries_cloudagent.core.profile INFO Create profile manager: askar
2023-04-05 17:09:04,271 aries_askar.native.aries_askar.ffi.log DEBUG    src/ffi/log.rs:123 | Initialized custom logger
2023-04-05 17:09:04,272 aries_askar.native.aries_askar.backend.any DEBUG    src/backend/any.rs:256 | Open store with options: Options { schema: "postgres", user: "******", password: "******", host: "aries-mediator-db-askar:5432", path: "/aries-mediator-agent-askar-wallet", query: {"admin_password": "******", "admin_account": "postgres"}, fragment: "" }
2023-04-05 17:09:04,295 aries_askar.native.aries_askar.backend.any DEBUG    src/backend/any.rs:291 | Provision store with options: Options { schema: "postgres", user: "******", password: "******", host: "aries-mediator-db-askar:5432", path: "/aries-mediator-agent-askar-wallet", query: {"admin_account": "postgres", "admin_password": "******"}, fragment: "" }
2023-04-05 17:09:04,374 aries_askar.native.sqlx.query INFO  None:0 | CREATE DATABASE "aries-mediator-agent-askar-wallet"; rows affected: 0, rows returned: 0, elapsed: 45.229ms
2023-04-05 17:09:04,427 aries_askar.native.sqlx.query DEBUG     None:0 | BEGIN; rows affected: 0, rows returned: 0, elapsed: 281.865µs
2023-04-05 17:09:04,431 aries_askar.native.sqlx.query DEBUG     None:0 | SELECT COUNT(*) FROM information_schema.tables …; rows affected: 0, rows returned: 1, elapsed: 2.833ms

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

2023-04-05 17:09:06,073 aries_askar.native.sqlx.query DEBUG     None:0 | CREATE TABLE config ( …; rows affected: 0, rows returned: 0, elapsed: 713.850µ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-05 17:09:06,074 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: permission denied for schema public

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-05 17:09:06,080 aries_askar.native.aries_askar.ffi.log DEBUG    src/ffi/log.rs:130 | Removing custom logger

cc @swcurran, @andrewwhitehead

WadeBarnes commented 1 year ago

Going to try v13 now.

swcurran commented 1 year ago

Do we just say not supported? I used Postgres 15 yesterday in docker and it worked fine.

WadeBarnes commented 1 year ago

I'd like to fine out why there is a permission error creating the schema.

andrewwhitehead commented 1 year ago

I assume it's this issue (needing an additional GRANT): https://stackoverflow.com/a/74111630

WadeBarnes commented 1 year ago

That would be on the Askar side during database creation, correct?

andrewwhitehead commented 1 year ago

I believe so, if it's the one creating the database.

WadeBarnes commented 1 year ago

I believe so, if it's the one creating the database.

It is

shaangill025 commented 1 year ago

I think this can also be resolved when standing up postgres instance by assigning SUPERUSER role which will bypass the permission issues.

https://github.com/hyperledger/aries-cloudagent-python/blob/8e6b520dec75f5b8f2d4104004861a90bb2a1192/demo/docker-test/db/init-postgres-role.sh#L5

WadeBarnes commented 1 year ago

It's working with the redhat Postgres 13.7 container.

WadeBarnes commented 1 year ago

I think this can also be resolved when standing up postgres instance by assigning SUPERUSER role which will bypass the permission issues.

https://github.com/hyperledger/aries-cloudagent-python/blob/8e6b520dec75f5b8f2d4104004861a90bb2a1192/demo/docker-test/db/init-postgres-role.sh#L5

Not something we want to do in our deployment environments.

swcurran commented 1 year ago

We need to know if this is urgent for 0.8.1 or can we wait? Also what are the steps needed to include the fix in the release? Do we know what and where the fix is?

Thanks!

swcurran commented 1 year ago

And one more question — do we know the scope of the issue? What changed in (presumably) Postgres that caused this and in what Postgres release?

shaangill025 commented 1 year ago

I have been using the following docker compose to test for this issue, I was able to replicate the previous reported error with postgres 10 but 15 for me is working:

version: "3"
services:
  vcr-agent:
    image: bcgovimages/aries-cloudagent:py36-1.16-1_0.8.1-rc2
    ports:
      - 8010:8010
      - 8001:8001
    networks:
      - wallet-net
    entrypoint: /bin/bash
    depends_on:
      - wallet-db
    environment:
      - WAIT_BEFORE_HOSTS=5
      - WAIT_HOSTS=wallet-db:5432
      - WAIT_HOSTS_TIMEOUT=120
      - WAIT_HOST_CONNECT_TIMEOUT=60
    command: [
        "-c",
        "sleep 5; \
        aca-py start \
        --auto-provision \
        # --recreate-wallet \
        --seed '00000000o_faber_secondary_school' \
        --inbound-transport http '0.0.0.0' 8001 \
        --endpoint 'http://host.docker.internal:8001' \
        --outbound-transport http \
        --genesis-url 'http://test.bcovrin.vonx.io/genesis' \
        --auto-accept-invites \
        --auto-accept-requests \
        --auto-ping-connection \
        --auto-respond-messages \
        --auto-respond-credential-proposal \
        --auto-respond-credential-offer \
        --auto-respond-credential-request \
        --auto-verify-presentation \
        --wallet-type 'askar' \
        --wallet-name 'acapy_agent_wallet' \
        --wallet-key 'key' \
        --wallet-storage-type 'postgres_storage' \
        --wallet-storage-config '{\"url\":\"wallet-db:5432\",\"max_connections\":5}' \
        --wallet-storage-creds '{\"account\":\"DB_USER\",\"password\":\"DB_PASSWORD\",\"admin_account\":\"DB_USER\",\"admin_password\":\"DB_PASSWORD\"}' \
        --admin '0.0.0.0' 8010 \
        --admin-insecure-mode \
        --label 'tester_agent' \
        --log-level 'debug' ",
      ]

  wallet-db:
    image: postgres:15
    environment:
      - POSTGRES_USER=DB_USER
      - POSTGRES_PASSWORD=DB_PASSWORD
    networks:
      - wallet-net
    ports:
      - 5432:5432
    volumes:
      - wallet-db-data:/var/lib/pgsql/data

volumes:
  wallet-db-data:

networks:
  wallet-net:
    external:
      name: docker-test_wallet-net
swcurran commented 1 year ago

I believe the plan is to not address this prior to 0.8.1. What we will do:

Sound right?

WadeBarnes commented 1 year ago

Sounds good. We can use Postgres 14.x on OCP for now. I'm going to quickly try one or two more tests to see if it's the container or Postgres version or a combination that is causing the issue.

So far:

Update - The issue seems to be related to the Postgres version, not the container implementation.

MonolithicMonk commented 1 year ago

A few observations and configuration proposed resolution before an askar fix is deployed.

As previously mentioned, postgres 15 has updated schema permissions in a way that none DB owners do not have the CREATE permission specific to a database unless granted. What this means is that the user that creates a database (including admin) is the only one with permission to create tables in the schema, in this case public.

With the published configurations, especially the ones related to kubernetes, the wallet-storage-creds settings is configured with the postgres user and password for the admin details. So when acapy initializes, it attempts to login using the regular postgres username, password, and database name. Of course it doesn't find a database with that name, so it creates one.

The problem is, when it creates a database, it does so using the the configured admin details. Meaning that the owner of the database is postgres. During subsequent transactions, it reverts to using the regular user's details which doesn't have the correct permissions. Hence the permission error.

The reason the docker configurations work, is that the wallet-storage-creds is configured with the regular user and password as the admin details. This of course requires that the database user is pre created with the CREATEDB permission granted.

Unless, there is a specific reason to use the admin user details as admin configuration, simply using the regular for both works great

andrewwhitehead commented 1 year ago

The new guidelines for schemas suggest to me that we should be using a schema named after the database user, rather than the default schema (public): https://www.postgresql.org/docs/15/ddl-schemas.html#DDL-SCHEMAS-PATTERNS

I believe this would also allow for multiple schemas within the same database, which could be desirable.

swcurran commented 1 year ago

This is now supported in the upcoming Askar release (0.3.0). Currently there is a release candidate ("dev1") for Askar 0.3.0. We need to decide when we want to update the ACA-Py requirements to start to use the 0.3.0 version -- do we go with the "devX" ones, or wait until the final 0.3.0 tag? TBD still.

swcurran commented 1 year ago

@WadeBarnes --- are you able to create a way to test deploying ACA-Py with Askar 0.3.0-dev1 on OpenShift? Do you need something done to enable that -- e.g. changing the ACA-Py dependency on main. @andrewwhitehead thinks this is complete and that Postgres 15 should work on OpenShift with the Askar updates he has done.

swcurran commented 10 months ago

We've not heard back from previous comment about if this is now working on OpenShift. We'll go with the assumption it is working and so are closing this. Please open a new issue if there is something else found.