search

bcgov / aries-acapy-plugin-redis-events

Apache License 2.0
5 stars 13 forks source link

Existing installations of ACA-Py are downgraded when installing this plugin #23

Closed WadeBarnes closed 11 months ago

WadeBarnes commented 11 months ago

When building a persistent queue mediator instance using this Dockerfile and overriding the FROM to use ghcr.io/hyperledger/aries-cloudagent-python:py3.9-0.10.4, the resulting image contains ACA-Py 0.8.2. The plugin install step unexpectedly downgrades the ACA-Py version.

build.log

The resulting image encounters startup errors. This new image was upgrading an existing, working, image.

2023-10-24 20:24:21,866 aries_cloudagent.resolver WARNING Ledger is not configured, not loading IndyDIDResolver
2023-10-24 20:24:21,867 redis_queue.v1_0.events INFO subscribing to event: ^acapy::webhook::(.*)$
2023-10-24 20:24:21,867 redis_queue.v1_0.events INFO subscribing to event: ^acapy::record::([^:]*)::([^:]*)$
2023-10-24 20:24:21,867 redis_queue.v1_0.events INFO subscribing to event: ^acapy::record::([^:])?
2023-10-24 20:24:21,867 redis_queue.v1_0.events INFO subscribing to event: acapy::basicmessage::received
2023-10-24 20:24:21,867 redis_queue.v1_0.events INFO subscribing to event: acapy::problem_report
2023-10-24 20:24:21,867 redis_queue.v1_0.events INFO subscribing to event: acapy::ping::received
2023-10-24 20:24:21,868 redis_queue.v1_0.events INFO subscribing to event: acapy::ping::response_received
2023-10-24 20:24:21,868 redis_queue.v1_0.events INFO subscribing to event: acapy::actionmenu::received
2023-10-24 20:24:21,868 redis_queue.v1_0.events INFO subscribing to event: acapy::actionmenu::get-active-menu
2023-10-24 20:24:21,868 redis_queue.v1_0.events INFO subscribing to event: acapy::actionmenu::perform-menu-action
2023-10-24 20:24:21,868 redis_queue.v1_0.events INFO subscribing to event: acapy::keylist::updated
2023-10-24 20:24:21,868 redis_queue.v1_0.events INFO subscribing to event: acapy::revocation-notification::received
2023-10-24 20:24:21,868 redis_queue.v1_0.events INFO subscribing to event: acapy::revocation-notification-v2::received
2023-10-24 20:24:21,868 redis_queue.v1_0.events INFO subscribing to event: acapy::forward::received
2023-10-24 20:24:21,996 aries_cloudagent.core.profile INFO Create profile manager: askar
2023-10-24 20:24:22,781 aries_cloudagent.askar.profile INFO Ledger support is disabled
2023-10-24 20:24:22,790 aries_cloudagent.config.ledger INFO Ledger instance not provided
2023-10-24 20:24:22,790 aries_cloudagent.core.conductor WARNING No ledger configured

::::::::::::::::::::::::::::::::::::::::::::::
:: BC Mediator (pq)(Dev)                    ::
::                                          ::
::                                          ::
:: Inbound Transports:                      ::
::                                          ::
::   - http://0.0.0.0:3000                  ::
::   - ws://0.0.0.0:3001                    ::
::                                          ::
:: Outbound Transports:                     ::
::                                          ::
::   - http                                 ::
::   - https                                ::
::   - ws                                   ::
::   - wss                                  ::
::                                          ::
:: Public DID Information:                  ::
::                                          ::
::   - DID: 3TbfvFPs93ZV2P8RgPfoAs          ::
::                                          ::
:: Administration API:                      ::
::                                          ::
::   - http://0.0.0.0:3002                  ::
::                                          ::
::                               ver: 0.8.2 ::
::::::::::::::::::::::::::::::::::::::::::::::

Listening...

2023-10-24 20:24:22,912 aries_cloudagent.core.conductor INFO Existing acapy_version storage record found, version set to v0.8.1
2023-10-24 20:24:22,918 aries_cloudagent.commands.upgrade INFO Running upgrade process for v0.8.1
2023-10-24 20:24:26,708 aiohttp.access INFO 10.97.128.1 [24/Oct/2023:20:24:26 +0000] "GET / HTTP/1.1" 200 168 "-" "kube-probe/1.25"
2023-10-24 20:24:36,708 aiohttp.access INFO 10.97.128.1 [24/Oct/2023:20:24:36 +0000] "GET / HTTP/1.1" 200 168 "-" "kube-probe/1.25"
2023-10-24 20:24:46,707 aiohttp.access INFO 10.97.128.1 [24/Oct/2023:20:24:46 +0000] "GET / HTTP/1.1" 200 168 "-" "kube-probe/1.25"
2023-10-24 20:24:50,448 aries_cloudagent.commands.upgrade INFO All recs of <class 'aries_cloudagent.connections.models.conn_record.ConnRecord'> successfully re-saved
2023-10-24 20:24:50,451 aries_cloudagent.commands.upgrade INFO acapy_version storage record set to v0.8.2
2023-10-24 20:24:56,752 aiohttp.access INFO 10.97.128.1 [24/Oct/2023:20:24:56 +0000] "GET / HTTP/1.1" 200 168 "-" "kube-probe/1.25"
2023-10-24 20:25:02,832 aries_cloudagent.core.event_bus ERROR Error occurred while processing event
Traceback (most recent call last):
  File "/usr/local/lib/python3.9/site-packages/redis/asyncio/connection.py", line 577, in connect
    await self.retry.call_with_retry(
  File "/usr/local/lib/python3.9/site-packages/redis/asyncio/retry.py", line 59, in call_with_retry
    return await do()
  File "/usr/local/lib/python3.9/site-packages/redis/asyncio/connection.py", line 922, in _connect
    reader, writer = await asyncio.open_connection(
  File "/usr/local/lib/python3.9/asyncio/streams.py", line 52, in open_connection
    transport, _ = await loop.create_connection(
  File "/usr/local/lib/python3.9/asyncio/base_events.py", line 1065, in create_connection
    raise exceptions[0]
  File "/usr/local/lib/python3.9/asyncio/base_events.py", line 1050, in create_connection
    sock = await self._connect_sock(
  File "/usr/local/lib/python3.9/asyncio/base_events.py", line 961, in _connect_sock
    await self.sock_connect(sock, address)
  File "/usr/local/lib/python3.9/asyncio/selector_events.py", line 500, in sock_connect
    return await fut
  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
  File "/usr/local/lib/python3.9/asyncio/selector_events.py", line 535, in _sock_connect_cb
    raise OSError(err, f'Connect call failed {address}')
OSError: [Errno 113] Connect call failed ('10.97.52.142', 6379)

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/usr/local/lib/python3.9/site-packages/redis_queue/v1_0/events/__init__.py", line 48, in redis_setup
    await redis.ping(target_nodes=RedisCluster.PRIMARIES)
  File "/usr/local/lib/python3.9/site-packages/redis/asyncio/cluster.py", line 725, in execute_command
    raise e
  File "/usr/local/lib/python3.9/site-packages/redis/asyncio/cluster.py", line 704, in execute_command
    values = await asyncio.gather(
  File "/usr/local/lib/python3.9/asyncio/tasks.py", line 328, in __wakeup
    future.result()
  File "/usr/local/lib/python3.9/asyncio/tasks.py", line 256, in __step
    result = coro.send(None)
  File "/usr/local/lib/python3.9/site-packages/redis/asyncio/cluster.py", line 750, in _execute_command
    return await target_node.execute_command(*args, **kwargs)
  File "/usr/local/lib/python3.9/site-packages/redis/asyncio/cluster.py", line 1016, in execute_command
    await connection.send_packed_command(connection.pack_command(*args), False)
  File "/usr/local/lib/python3.9/site-packages/redis/asyncio/connection.py", line 713, in send_packed_command
    await self.connect()
  File "/usr/local/lib/python3.9/site-packages/redis/asyncio/connection.py", line 585, in connect
    raise ConnectionError(self._error_message(e))
redis.exceptions.ConnectionError: Error 113 connecting to 10.97.52.142:6379. 113.

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/usr/local/lib/python3.9/site-packages/aries_cloudagent/core/event_bus.py", line 121, in notify
    await processor()
  File "/usr/local/lib/python3.9/site-packages/redis_queue/v1_0/events/__init__.py", line 84, in handle_event
    redis = await redis_setup(profile, event)
  File "/usr/local/lib/python3.9/site-packages/redis_queue/v1_0/events/__init__.py", line 51, in redis_setup
    raise TransportError(f"No Redis instance setup, {err}")
aries_cloudagent.transport.error.TransportError: No Redis instance setup, Error 113 connecting to 10.97.52.142:6379. 113.
2023-10-24 20:25:05,968 aries_cloudagent.core.event_bus ERROR Error occurred while processing event
Traceback (most recent call last):
  File "/usr/local/lib/python3.9/site-packages/redis/asyncio/connection.py", line 577, in connect
    await self.retry.call_with_retry(
  File "/usr/local/lib/python3.9/site-packages/redis/asyncio/retry.py", line 59, in call_with_retry
    return await do()
  File "/usr/local/lib/python3.9/site-packages/redis/asyncio/connection.py", line 922, in _connect
    reader, writer = await asyncio.open_connection(
  File "/usr/local/lib/python3.9/asyncio/streams.py", line 52, in open_connection
    transport, _ = await loop.create_connection(
  File "/usr/local/lib/python3.9/asyncio/base_events.py", line 1065, in create_connection
    raise exceptions[0]
  File "/usr/local/lib/python3.9/asyncio/base_events.py", line 1050, in create_connection
    sock = await self._connect_sock(
  File "/usr/local/lib/python3.9/asyncio/base_events.py", line 961, in _connect_sock
    await self.sock_connect(sock, address)
  File "/usr/local/lib/python3.9/asyncio/selector_events.py", line 500, in sock_connect
    return await fut
  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
  File "/usr/local/lib/python3.9/asyncio/selector_events.py", line 535, in _sock_connect_cb
    raise OSError(err, f'Connect call failed {address}')
OSError: [Errno 113] Connect call failed ('10.97.58.97', 6379)

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/usr/local/lib/python3.9/site-packages/redis_queue/v1_0/events/__init__.py", line 48, in redis_setup
    await redis.ping(target_nodes=RedisCluster.PRIMARIES)
  File "/usr/local/lib/python3.9/site-packages/redis/asyncio/cluster.py", line 676, in execute_command
    await self.initialize()
  File "/usr/local/lib/python3.9/site-packages/redis/asyncio/cluster.py", line 384, in initialize
    await self.commands_parser.initialize(
  File "/usr/local/lib/python3.9/site-packages/redis/asyncio/parser.py", line 34, in initialize
    commands = await self.node.execute_command("COMMAND")
  File "/usr/local/lib/python3.9/site-packages/redis/asyncio/cluster.py", line 1016, in execute_command
    await connection.send_packed_command(connection.pack_command(*args), False)
  File "/usr/local/lib/python3.9/site-packages/redis/asyncio/connection.py", line 713, in send_packed_command
    await self.connect()
  File "/usr/local/lib/python3.9/site-packages/redis/asyncio/connection.py", line 585, in connect
    raise ConnectionError(self._error_message(e))
redis.exceptions.ConnectionError: Error 113 connecting to 10.97.58.97:6379. 113.

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/usr/local/lib/python3.9/site-packages/aries_cloudagent/core/event_bus.py", line 121, in notify
    await processor()
  File "/usr/local/lib/python3.9/site-packages/redis_queue/v1_0/events/__init__.py", line 84, in handle_event
    redis = await redis_setup(profile, event)
  File "/usr/local/lib/python3.9/site-packages/redis_queue/v1_0/events/__init__.py", line 51, in redis_setup
    raise TransportError(f"No Redis instance setup, {err}")
aries_cloudagent.transport.error.TransportError: No Redis instance setup, Error 113 connecting to 10.97.58.97:6379. 113.
Invitation URL (Connections protocol):

Displays invite here ...

2023-10-24 20:25:06,599 aiohttp.access INFO 10.97.114.64 [24/Oct/2023:20:25:06 +0000] "GET /status/ready HTTP/1.1" 200 172 "-" "kube-probe/1.25"
2023-10-24 20:25:06,706 aiohttp.access INFO 10.97.128.1 [24/Oct/2023:20:25:06 +0000] "GET / HTTP/1.1" 200 168 "-" "kube-probe/1.25"
2023-10-24 20:25:16,707 aiohttp.access INFO 10.97.128.1 [24/Oct/2023:20:25:16 +0000] "GET / HTTP/1.1" 200 168 "-" "kube-probe/1.25"
2023-10-24 20:25:18,448 aries_cloudagent.core.event_bus ERROR Error occurred while processing event
Traceback (most recent call last):
  File "/usr/local/lib/python3.9/site-packages/redis/asyncio/connection.py", line 577, in connect
    await self.retry.call_with_retry(
  File "/usr/local/lib/python3.9/site-packages/redis/asyncio/retry.py", line 59, in call_with_retry
    return await do()
  File "/usr/local/lib/python3.9/site-packages/redis/asyncio/connection.py", line 922, in _connect
    reader, writer = await asyncio.open_connection(
  File "/usr/local/lib/python3.9/asyncio/streams.py", line 52, in open_connection
    transport, _ = await loop.create_connection(
  File "/usr/local/lib/python3.9/asyncio/base_events.py", line 1065, in create_connection
    raise exceptions[0]
  File "/usr/local/lib/python3.9/asyncio/base_events.py", line 1050, in create_connection
    sock = await self._connect_sock(
  File "/usr/local/lib/python3.9/asyncio/base_events.py", line 961, in _connect_sock
    await self.sock_connect(sock, address)
  File "/usr/local/lib/python3.9/asyncio/selector_events.py", line 500, in sock_connect
    return await fut
  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
  File "/usr/local/lib/python3.9/asyncio/selector_events.py", line 535, in _sock_connect_cb
    raise OSError(err, f'Connect call failed {address}')
OSError: [Errno 113] Connect call failed ('10.97.52.142', 6379)

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/usr/local/lib/python3.9/site-packages/redis_queue/v1_0/events/__init__.py", line 48, in redis_setup
    await redis.ping(target_nodes=RedisCluster.PRIMARIES)
  File "/usr/local/lib/python3.9/site-packages/redis/asyncio/cluster.py", line 725, in execute_command
    raise e
  File "/usr/local/lib/python3.9/site-packages/redis/asyncio/cluster.py", line 704, in execute_command
    values = await asyncio.gather(
  File "/usr/local/lib/python3.9/asyncio/tasks.py", line 328, in __wakeup
    future.result()
  File "/usr/local/lib/python3.9/asyncio/tasks.py", line 256, in __step
    result = coro.send(None)
  File "/usr/local/lib/python3.9/site-packages/redis/asyncio/cluster.py", line 750, in _execute_command
    return await target_node.execute_command(*args, **kwargs)
  File "/usr/local/lib/python3.9/site-packages/redis/asyncio/cluster.py", line 1016, in execute_command
    await connection.send_packed_command(connection.pack_command(*args), False)
  File "/usr/local/lib/python3.9/site-packages/redis/asyncio/connection.py", line 713, in send_packed_command
    await self.connect()
  File "/usr/local/lib/python3.9/site-packages/redis/asyncio/connection.py", line 585, in connect
    raise ConnectionError(self._error_message(e))
redis.exceptions.ConnectionError: Error 113 connecting to 10.97.52.142:6379. 113.

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/usr/local/lib/python3.9/site-packages/aries_cloudagent/core/event_bus.py", line 121, in notify
    await processor()
  File "/usr/local/lib/python3.9/site-packages/redis_queue/v1_0/events/__init__.py", line 56, in on_startup
    await redis_setup(profile, event)
  File "/usr/local/lib/python3.9/site-packages/redis_queue/v1_0/events/__init__.py", line 51, in redis_setup
    raise TransportError(f"No Redis instance setup, {err}")
aries_cloudagent.transport.error.TransportError: No Redis instance setup, Error 113 connecting to 10.97.52.142:6379. 113.
WadeBarnes commented 11 months ago

I would expect the plugin install to fail if it was not compatible with the existing version of ACA-Py, but downgrading the ACA-Py version is the wrong thing to do.

WadeBarnes commented 11 months ago

The release notes indicate the latest version of the plugin should be used with ACA-Py >=0.9.0

WadeBarnes commented 11 months ago

Startup error may have been due to an unsynchronized Redis cluster. I need to try the deployment again.