hook failed: "s3-parameters-relation-changed" with IndexError: list index out of range

[hloeung]

Steps to reproduce

1. Deploy 3 postgresql units using Terraform
2. Deploy 1 S3 integrator unit using Terraform
3. Relate the two
4. These are in OpenStack (prodstack6)

Expected behavior

All 3 postgresql units up and running and backups configured to S3.

Actual behavior

postgresql/0*             error     idle   3        10.146.64.60    5432/tcp  hook failed: "s3-parameters-relation-changed"
  grafana-agent/2         blocked   idle            10.146.64.60              Missing ['grafana-cloud-config']|['grafana-dashboards-provider']|['logging-consumer']|['send-remote-write'] for cos-a...
  landscape-client/3      active    idle            10.146.64.60              Client registered!
  telegraf/3              active    idle            10.146.64.60    9103/tcp  Monitoring postgresql/0 (source version/commit 23.10)
  ubuntu-advantage/3      active    idle            10.146.64.60              Attached (esm-apps,esm-infra,livepatch)
postgresql/1              waiting   idle   4        10.146.64.56    5432/tcp  awaiting for cluster to start
  grafana-agent/3         blocked   idle            10.146.64.56              Missing ['grafana-cloud-config']|['grafana-dashboards-provider']|['logging-consumer']|['send-remote-write'] for cos-a...
  landscape-client/4      active    idle            10.146.64.56              Client registered!
  telegraf/4              active    idle            10.146.64.56    9103/tcp  Monitoring postgresql/1 (source version/commit 23.10)
  ubuntu-advantage/4      active    idle            10.146.64.56              Attached (esm-apps,esm-infra,livepatch)
postgresql/2              waiting   idle   5        10.146.64.57    5432/tcp  waiting to start PostgreSQL
  grafana-agent/4         blocked   idle            10.146.64.57              Missing ['grafana-cloud-config']|['grafana-dashboards-provider']|['logging-consumer']|['send-remote-write'] for cos-a...
  landscape-client/5      active    idle            10.146.64.57              Client registered!
  telegraf/5              active    idle            10.146.64.57    9103/tcp  Monitoring postgresql/2 (source version/commit 23.10)
  ubuntu-advantage/5      active    idle            10.146.64.57              Attached (esm-apps,esm-infra,livepatch)

Versions

Operating system: Ubuntu 22.04.5 LTS

Juju CLI: 3.5.5-ubuntu-amd64

Juju agent: 3.5.5

Charm revision: 14/edge r541

Log output

Juju debug log:

ubuntu@juju-fcb6bc-is-managed-database-testing-dbaas-3:~$ tail -f /var/log/juju/unit-postgresql-0.log  -n 100
2025-01-13 23:15:05 DEBUG unit.postgresql/0.juju-log server.go:325 s3-parameters:25: Event before-call.s3.HeadObject: calling handler <function add_expect_header at 0x7f6ce95d17e0>
2025-01-13 23:15:05 DEBUG unit.postgresql/0.juju-log server.go:325 s3-parameters:25: Event before-call.s3.HeadObject: calling handler <bound method S3ExpressIdentityResolver.apply_signing_cache_key of <botocore.utils.S3ExpressIdentityResolver object at 0x7f6ce2bd7070>>
2025-01-13 23:15:05 DEBUG unit.postgresql/0.juju-log server.go:325 s3-parameters:25: Event before-call.s3.HeadObject: calling handler <function add_recursion_detection_header at 0x7f6ce95d0ee0>
2025-01-13 23:15:05 DEBUG unit.postgresql/0.juju-log server.go:325 s3-parameters:25: Event before-call.s3.HeadObject: calling handler <function add_query_compatibility_header at 0x7f6ce95d3910>
2025-01-13 23:15:05 DEBUG unit.postgresql/0.juju-log server.go:325 s3-parameters:25: Event before-call.s3.HeadObject: calling handler <function inject_api_version_header_if_needed at 0x7f6ce95d2b00>
2025-01-13 23:15:05 DEBUG unit.postgresql/0.juju-log server.go:325 s3-parameters:25: Making request for OperationModel(name=HeadObject) with params: {'url_path': '/is-managed-database-testing-dbaas/model-uuid.txt', 'query_string': {}, 'method': 'HEAD', 'headers': {'User-Agent': 'Boto3/1.35.87 md/Botocore#1.35.87 ua/2.0 os/linux#5.15.0-130-generic md/arch#x86_64 lang/python#3.10.12 md/pyimpl#CPython cfg/retry-mode#legacy Botocore/1.35.87 Resource'}, 'body': b'', 'auth_path': '/is-managed-database-testing-dbaas-backup/is-managed-database-testing-dbaas/model-uuid.txt', 'url': 'https://radosgw.ps6.canonical.com/is-managed-database-testing-dbaas-backup/is-managed-database-testing-dbaas/model-uuid.txt', 'context': {'client_region': 'prodstack6', 'client_config': <botocore.config.Config object at 0x7f6ce9275270>, 'has_streaming_input': False, 'auth_type': 'v4', 'unsigned_payload': None, 's3_redirect': {'redirected': False, 'bucket': 'is-managed-database-testing-dbaas-backup', 'params': {'Bucket': 'is-managed-database-testing-dbaas-backup', 'Key': 'is-managed-database-testing-dbaas/model-uuid.txt'}}, 'input_params': {'Bucket': 'is-managed-database-testing-dbaas-backup', 'Key': 'is-managed-database-testing-dbaas/model-uuid.txt'}, 'signing': {'region': 'prodstack6', 'signing_name': 's3', 'disableDoubleEncoding': True}, 'endpoint_properties': {'authSchemes': [{'disableDoubleEncoding': True, 'name': 'sigv4', 'signingName': 's3', 'signingRegion': 'prodstack6'}]}}}
2025-01-13 23:15:05 DEBUG unit.postgresql/0.juju-log server.go:325 s3-parameters:25: Event request-created.s3.HeadObject: calling handler <function signal_not_transferring at 0x7f6ce3554ee0>
2025-01-13 23:15:05 DEBUG unit.postgresql/0.juju-log server.go:325 s3-parameters:25: Event request-created.s3.HeadObject: calling handler <bound method RequestSigner.handler of <botocore.signers.RequestSigner object at 0x7f6ce9274c40>>
2025-01-13 23:15:05 DEBUG unit.postgresql/0.juju-log server.go:325 s3-parameters:25: Event choose-signer.s3.HeadObject: calling handler <function set_operation_specific_signer at 0x7f6ce95d1120>
2025-01-13 23:15:05 DEBUG unit.postgresql/0.juju-log server.go:325 s3-parameters:25: Event before-sign.s3.HeadObject: calling handler <function remove_arn_from_signing_path at 0x7f6ce95d3400>
2025-01-13 23:15:05 DEBUG unit.postgresql/0.juju-log server.go:325 s3-parameters:25: Event before-sign.s3.HeadObject: calling handler <bound method S3ExpressIdentityResolver.resolve_s3express_identity of <botocore.utils.S3ExpressIdentityResolver object at 0x7f6ce2bd7070>>
2025-01-13 23:15:05 DEBUG unit.postgresql/0.juju-log server.go:325 s3-parameters:25: Calculating signature using v4 auth.
2025-01-13 23:15:05 DEBUG unit.postgresql/0.juju-log server.go:325 s3-parameters:25: CanonicalRequest:
HEAD
/is-managed-database-testing-dbaas-backup/is-managed-database-testing-dbaas/model-uuid.txt

host:radosgw.ps6.canonical.com
x-amz-content-sha256:e3b0c44298fc1c149afbf4c8996fb92427ae41e4649b934ca495991b7852b855
x-amz-date:20250113T231505Z

host;x-amz-content-sha256;x-amz-date
e3b0c44298fc1c149afbf4c8996fb92427ae41e4649b934ca495991b7852b855
2025-01-13 23:15:05 DEBUG unit.postgresql/0.juju-log server.go:325 s3-parameters:25: StringToSign:
AWS4-HMAC-SHA256
20250113T231505Z
20250113/prodstack6/s3/aws4_request
beb6644614d300e4ed8b4c2f21251a679407712840aaa229ae82b5680464e7c7
2025-01-13 23:15:05 DEBUG unit.postgresql/0.juju-log server.go:325 s3-parameters:25: Signature:
ea700809ed126fd67a00743070ab9187ad75d89af7d59efc8d81dad0d25c6169
2025-01-13 23:15:05 DEBUG unit.postgresql/0.juju-log server.go:325 s3-parameters:25: Event request-created.s3.HeadObject: calling handler <function signal_transferring at 0x7f6ce3554f70>
2025-01-13 23:15:05 DEBUG unit.postgresql/0.juju-log server.go:325 s3-parameters:25: Event request-created.s3.HeadObject: calling handler <function add_retry_headers at 0x7f6ce95d3250>
2025-01-13 23:15:05 DEBUG unit.postgresql/0.juju-log server.go:325 s3-parameters:25: Sending http request: <AWSPreparedRequest stream_output=False, method=HEAD, url=https://radosgw.ps6.canonical.com/is-managed-database-testing-dbaas-backup/is-managed-database-testing-dbaas/model-uuid.txt, headers={'User-Agent': b'Boto3/1.35.87 md/Botocore#1.35.87 ua/2.0 os/linux#5.15.0-130-generic md/arch#x86_64 lang/python#3.10.12 md/pyimpl#CPython cfg/retry-mode#legacy Botocore/1.35.87 Resource', 'X-Amz-Date': b'20250113T231505Z', 'X-Amz-Content-SHA256': b'e3b0c44298fc1c149afbf4c8996fb92427ae41e4649b934ca495991b7852b855', 'Authorization': b'AWS4-HMAC-SHA256 Credential=7ced5bca2d7f424f94600215878ad169/20250113/prodstack6/s3/aws4_request, SignedHeaders=host;x-amz-content-sha256;x-amz-date, Signature=ea700809ed126fd67a00743070ab9187ad75d89af7d59efc8d81dad0d25c6169', 'amz-sdk-invocation-id': b'bc8ca7fe-b55b-49a5-98fa-7a1faa19b2e0', 'amz-sdk-request': b'attempt=1'}>
2025-01-13 23:15:05 DEBUG unit.postgresql/0.juju-log server.go:325 s3-parameters:25: Certificate path: /var/lib/juju/agents/unit-postgresql-0/charm/venv/certifi/cacert.pem
2025-01-13 23:15:05 DEBUG unit.postgresql/0.juju-log server.go:325 s3-parameters:25: Starting new HTTPS connection (1): radosgw.ps6.canonical.com:443
2025-01-13 23:15:05 DEBUG unit.postgresql/0.juju-log server.go:325 s3-parameters:25: https://radosgw.ps6.canonical.com:443 "HEAD /is-managed-database-testing-dbaas-backup/is-managed-database-testing-dbaas/model-uuid.txt HTTP/1.1" 404 0
2025-01-13 23:15:05 DEBUG unit.postgresql/0.juju-log server.go:325 s3-parameters:25: Event before-parse.s3.HeadObject: calling handler <function _handle_200_error at 0x7f6ce95d3760>
2025-01-13 23:15:05 DEBUG unit.postgresql/0.juju-log server.go:325 s3-parameters:25: Event before-parse.s3.HeadObject: calling handler <function handle_expires_header at 0x7f6ce95d35b0>
2025-01-13 23:15:05 DEBUG unit.postgresql/0.juju-log server.go:325 s3-parameters:25: Response headers: {'Date': 'Mon, 13 Jan 2025 23:15:05 GMT', 'Server': 'Apache/2.4.52 (Ubuntu)', 'Content-Length': '253', 'x-amz-request-id': 'tx000002329988cf316a579-0067859e79-5afce5e-default', 'Accept-Ranges': 'bytes', 'Content-Type': 'application/xml'}
2025-01-13 23:15:05 DEBUG unit.postgresql/0.juju-log server.go:325 s3-parameters:25: Response body:
b''
2025-01-13 23:15:05 DEBUG unit.postgresql/0.juju-log server.go:325 s3-parameters:25: Event needs-retry.s3.HeadObject: calling handler <function _update_status_code at 0x7f6ce95d3880>
2025-01-13 23:15:05 DEBUG unit.postgresql/0.juju-log server.go:325 s3-parameters:25: Event needs-retry.s3.HeadObject: calling handler <botocore.retryhandler.RetryHandler object at 0x7f6ce2bd6f50>
2025-01-13 23:15:05 DEBUG unit.postgresql/0.juju-log server.go:325 s3-parameters:25: No retry needed.
2025-01-13 23:15:05 DEBUG unit.postgresql/0.juju-log server.go:325 s3-parameters:25: Event needs-retry.s3.HeadObject: calling handler <bound method S3RegionRedirectorv2.redirect_from_error of <botocore.utils.S3RegionRedirectorv2 object at 0x7f6ce2bd7010>>
2025-01-13 23:15:05 DEBUG unit.postgresql/0.juju-log server.go:325 s3-parameters:25: Exception raised.
Traceback (most recent call last):
  File "/var/lib/juju/agents/unit-postgresql-0/charm/venv/s3transfer/tasks.py", line 265, in _main
    self._submit(transfer_future=transfer_future, **kwargs)
  File "/var/lib/juju/agents/unit-postgresql-0/charm/venv/s3transfer/download.py", line 352, in _submit
    response = client.head_object(
  File "/var/lib/juju/agents/unit-postgresql-0/charm/venv/botocore/client.py", line 569, in _api_call
    return self._make_api_call(operation_name, kwargs)
  File "/var/lib/juju/agents/unit-postgresql-0/charm/venv/botocore/client.py", line 1023, in _make_api_call
    raise error_class(parsed_response, operation_name)
botocore.exceptions.ClientError: An error occurred (404) when calling the HeadObject operation: Not Found
2025-01-13 23:15:05 DEBUG unit.postgresql/0.juju-log server.go:325 s3-parameters:25: Releasing acquire 0/None
2025-01-13 23:15:05 INFO unit.postgresql/0.juju-log server.go:325 s3-parameters:25: No such object to read from S3 bucket=is-managed-database-testing-dbaas-backup, path=is-managed-database-testing-dbaas/model-uuid.txt
2025-01-13 23:15:06 ERROR unit.postgresql/0.juju-log server.go:325 s3-parameters:25: Uncaught exception while in charm code:
Traceback (most recent call last):
  File "/var/lib/juju/agents/unit-postgresql-0/charm/./src/charm.py", line 1960, in <module>
    main(PostgresqlOperatorCharm)
  File "/var/lib/juju/agents/unit-postgresql-0/charm/venv/ops/__init__.py", line 343, in __call__
    return _main.main(charm_class=charm_class, use_juju_for_storage=use_juju_for_storage)
  File "/var/lib/juju/agents/unit-postgresql-0/charm/venv/ops/_main.py", line 543, in main
    manager.run()
  File "/var/lib/juju/agents/unit-postgresql-0/charm/venv/ops/_main.py", line 529, in run
    self._emit()
  File "/var/lib/juju/agents/unit-postgresql-0/charm/venv/ops/_main.py", line 518, in _emit
    _emit_charm_event(self.charm, self.dispatcher.event_name, self._juju_context)
  File "/var/lib/juju/agents/unit-postgresql-0/charm/venv/ops/_main.py", line 134, in _emit_charm_event
    event_to_emit.emit(*args, **kwargs)
  File "/var/lib/juju/agents/unit-postgresql-0/charm/venv/ops/framework.py", line 347, in emit
    framework._emit(event)
  File "/var/lib/juju/agents/unit-postgresql-0/charm/venv/ops/framework.py", line 857, in _emit
    self._reemit(event_path)
  File "/var/lib/juju/agents/unit-postgresql-0/charm/venv/ops/framework.py", line 947, in _reemit
    custom_handler(event)
  File "/var/lib/juju/agents/unit-postgresql-0/charm/lib/charms/data_platform_libs/v0/s3.py", line 768, in _on_relation_changed
    getattr(self.on, "credentials_changed").emit(
  File "/var/lib/juju/agents/unit-postgresql-0/charm/venv/ops/framework.py", line 347, in emit
    framework._emit(event)
  File "/var/lib/juju/agents/unit-postgresql-0/charm/venv/ops/framework.py", line 857, in _emit
    self._reemit(event_path)
  File "/var/lib/juju/agents/unit-postgresql-0/charm/venv/ops/framework.py", line 947, in _reemit
    custom_handler(event)
  File "/var/lib/juju/agents/unit-postgresql-0/charm/lib/charms/tempo_coordinator_k8s/v0/charm_tracing.py", line 1064, in wrapped_function
    return callable(*args, **kwargs)  # type: ignore
  File "/var/lib/juju/agents/unit-postgresql-0/charm/src/backups.py", line 788, in _on_s3_credential_changed
    self._on_s3_credential_changed_primary(event)
  File "/var/lib/juju/agents/unit-postgresql-0/charm/lib/charms/tempo_coordinator_k8s/v0/charm_tracing.py", line 1064, in wrapped_function
    return callable(*args, **kwargs)  # type: ignore
  File "/var/lib/juju/agents/unit-postgresql-0/charm/src/backups.py", line 805, in _on_s3_credential_changed_primary
    can_use_s3_repository, validation_message = self.can_use_s3_repository()
  File "/var/lib/juju/agents/unit-postgresql-0/charm/lib/charms/tempo_coordinator_k8s/v0/charm_tracing.py", line 1064, in wrapped_function
    return callable(*args, **kwargs)  # type: ignore
  File "/var/lib/juju/agents/unit-postgresql-0/charm/src/backups.py", line 215, in can_use_s3_repository
    system_identifier_from_stanza = str(stanza.get("db")[0]["system-id"])
IndexError: list index out of range
2025-01-13 23:15:06 ERROR juju.worker.uniter.operation runhook.go:180 hook "s3-parameters-relation-changed" (via hook dispatching script: dispatch) failed: exit status 1
2025-01-13 23:15:06 INFO juju.worker.uniter resolver.go:180 awaiting error resolution for "relation-changed" hook
^C

Additional context

[syncronize-issues-to-jira]

Thank you for reporting your feedback to us!

The internal ticket has been created: https://warthogs.atlassian.net/browse/DPE-6323.

This message was autogenerated

[hloeung]

I should note, this was a teardown / decommission and then re-provision for testing.

Likely relating to stuff not cleaned up in the backup bucket?

is-managed-database-testing-dbaas@is-bastion-ps6:~$ swift list is-managed-database-testing-dbaas-backup
is-managed-database-testing-dbaas/backup/is-managed-database-testing-dbaas.postgresql/20241213-102231F/backup.log
is-managed-database-testing-dbaas/backup/is-managed-database-testing-dbaas.postgresql/20241214-102231F/backup.log
is-managed-database-testing-dbaas/backup/is-managed-database-testing-dbaas.postgresql/20241215-102231F/backup.log
is-managed-database-testing-dbaas/backup/is-managed-database-testing-dbaas.postgresql/20241216-102231F/backup.log
is-managed-database-testing-dbaas/backup/is-managed-database-testing-dbaas.postgresql/20241217-102231F/backup.log
is-managed-database-testing-dbaas/backup/is-managed-database-testing-dbaas.postgresql/20241218-102231F/backup.log
is-managed-database-testing-dbaas/backup/is-managed-database-testing-dbaas.postgresql/20241219-102233F/backup.log
is-managed-database-testing-dbaas/backup/is-managed-database-testing-dbaas.postgresql/20241220-102234F/backup.log
is-managed-database-testing-dbaas/backup/is-managed-database-testing-dbaas.postgresql/20241221-102234F/backup.log
is-managed-database-testing-dbaas/backup/is-managed-database-testing-dbaas.postgresql/20241222-102232F/backup.log
is-managed-database-testing-dbaas/backup/is-managed-database-testing-dbaas.postgresql/20241223-102232F/backup.log
is-managed-database-testing-dbaas/backup/is-managed-database-testing-dbaas.postgresql/20241224-102232F/backup.log
is-managed-database-testing-dbaas/backup/is-managed-database-testing-dbaas.postgresql/20241225-102231F/backup.log
is-managed-database-testing-dbaas/backup/is-managed-database-testing-dbaas.postgresql/20241226-102232F/backup.log
is-managed-database-testing-dbaas/backup/is-managed-database-testing-dbaas.postgresql/20241227-102231F/backup.log
is-managed-database-testing-dbaas/backup/is-managed-database-testing-dbaas.postgresql/20241228-102231F/backup.log
is-managed-database-testing-dbaas/backup/is-managed-database-testing-dbaas.postgresql/20241229-102232F/backup.log
is-managed-database-testing-dbaas/backup/is-managed-database-testing-dbaas.postgresql/20241230-102232F/backup.log
is-managed-database-testing-dbaas/backup/is-managed-database-testing-dbaas.postgresql/20241231-102231F/backup.log
is-managed-database-testing-dbaas/backup/is-managed-database-testing-dbaas.postgresql/20250101-102234F/backup.log
is-managed-database-testing-dbaas/backup/is-managed-database-testing-dbaas.postgresql/20250102-102232F/backup.log
is-managed-database-testing-dbaas/backup/is-managed-database-testing-dbaas.postgresql/20250103-102231F/backup.log
is-managed-database-testing-dbaas/backup/is-managed-database-testing-dbaas.postgresql/20250104-102232F/backup.log
is-managed-database-testing-dbaas/backup/is-managed-database-testing-dbaas.postgresql/20250105-102232F/backup.log
is-managed-database-testing-dbaas/backup/is-managed-database-testing-dbaas.postgresql/20250106-102232F/backup.log
is-managed-database-testing-dbaas/backup/is-managed-database-testing-dbaas.postgresql/20250107-102234F/backup.log
is-managed-database-testing-dbaas/backup/is-managed-database-testing-dbaas.postgresql/20250108-102232F/backup.log
is-managed-database-testing-dbaas/backup/is-managed-database-testing-dbaas.postgresql/20250109-102232F/backup.log
is-managed-database-testing-dbaas/backup/is-managed-database-testing-dbaas.postgresql/20250110-102233F/backup.log
is-managed-database-testing-dbaas/backup/is-managed-database-testing-dbaas.postgresql/20250111-102233F/backup.log
is-managed-database-testing-dbaas/backup/is-managed-database-testing-dbaas.postgresql/20250112-102233F/backup.log
is-managed-database-testing-dbaas/backup/is-managed-database-testing-dbaas.postgresql/20250113-102234F/backup.log
is-managed-database-testing-dbaas/backup/is-managed-database-testing-dbaas.postgresql/latest
is-managed-database-testing-dbaas@is-bastion-ps6:~$

[hloeung]

Added pprint of stanza and I see this:

2025-01-13 23:29:39 INFO unit.postgresql/0.juju-log server.go:325 s3-parameters:25: No such object to read from S3 bucket=is-managed-database-testing-dbaas-backup, path=is-managed-database-testing-dbaas/model-uuid.txt
2025-01-13 23:29:39 DEBUG unit.postgresql/0.s3-parameters-relation-changed logger.go:60 {'archive': [],
2025-01-13 23:29:39 DEBUG unit.postgresql/0.s3-parameters-relation-changed logger.go:60  'backup': [],
2025-01-13 23:29:39 DEBUG unit.postgresql/0.s3-parameters-relation-changed logger.go:60  'cipher': 'none',
2025-01-13 23:29:39 DEBUG unit.postgresql/0.s3-parameters-relation-changed logger.go:60  'db': [],
2025-01-13 23:29:39 DEBUG unit.postgresql/0.s3-parameters-relation-changed logger.go:60  'name': 'is-managed-database-testing-dbaas.postgresql',
2025-01-13 23:29:39 DEBUG unit.postgresql/0.s3-parameters-relation-changed logger.go:60  'repo': [{'cipher': 'none',
2025-01-13 23:29:39 DEBUG unit.postgresql/0.s3-parameters-relation-changed logger.go:60            'key': 1,
2025-01-13 23:29:39 DEBUG unit.postgresql/0.s3-parameters-relation-changed logger.go:60            'status': {'code': 3, 'message': 'missing stanza data'}}],
2025-01-13 23:29:39 DEBUG unit.postgresql/0.s3-parameters-relation-changed logger.go:60  'status': {'code': 3,
2025-01-13 23:29:39 DEBUG unit.postgresql/0.s3-parameters-relation-changed logger.go:60             'lock': {'backup': {'held': False}},
2025-01-13 23:29:39 DEBUG unit.postgresql/0.s3-parameters-relation-changed logger.go:60             'message': 'missing stanza data'}}

[dragomirp]

Hi, @hloeung, opened #727 to handle the exception, but that's not the root cause of the problem. Is the bucket you are using empty?

[hloeung]

@dragomirp, it's not empty no. We did a tear down and the re-create/provisioning of the environment. Unfortunately, I did not clean up the bucket beforehand which is what led to this. Thanks for the fix.

[dragomirp]

Latest 14/edge (revs. 564, 565) should handle the exception.