k8ssandra / k8ssandra-terraform

Apache License 2.0
17 stars 16 forks source link

Backups fail with 403 errors with EKS clusters backing up to S3. #23

Closed bradfordcp closed 3 years ago

bradfordcp commented 3 years ago

Bug Report

Describe the bug Attempting to back up an EKS cluster to S3 shows 403 errors in Medusa logs. I've tried both IAM roles specified on the EC2 instances as well as manually specifying credentials in the Medusa Storage Secret.

To Reproduce Steps to reproduce the behavior:

EC2 Roles

  1. Create an EKS cluster with k8ssandra/terraform
  2. Create an empty secret for Medusa
  3. Install K8ssandra
  4. Create a backup

Manual IAM

  1. Create an EKS cluster with k8ssandra/terraform
  2. Create an IAM role with permissions to the S3 bucket generated via Terraform
  3. Create a Medusa secret with the IAM credentials
  4. Install K8ssandra
  5. Create a backup

Expected behavior I expect the S3 bucket to have the files generated by the backup operation

Environment (please complete the following information):

$ helm ls -A
NAME            NAMESPACE   REVISION    UPDATED                                 STATUS      CHART           APP VERSION
prod-k8ssandra  default     1           2021-04-30 15:17:09.031862215 -0400 EDT deployed    k8ssandra-1.1.0            
test            default     1           2021-04-30 15:33:39.283343328 -0400 EDT deployed    backup-0.26.0    

* Kubernetes version information:

Client Version: version.Info{Major:"1", Minor:"21", GitVersion:"v1.21.0", GitCommit:"cb303e613a121a29364f75cc67d3d580833a7479", GitTreeState:"clean", BuildDate:"2021-04-08T16:31:21Z", GoVersion:"go1.16.1", Compiler:"gc", Platform:"linux/amd64"} Server Version: version.Info{Major:"1", Minor:"19+", GitVersion:"v1.19.8-eks-96780e", GitCommit:"96780e1b30acbf0a52c38b6030d7853e575bcdf3", GitTreeState:"clean", BuildDate:"2021-03-10T21:32:29Z", GoVersion:"go1.15.8", Compiler:"gc", Platform:"linux/amd64"} WARNING: version difference between client (1.21) and server (1.19) exceeds the supported minor version skew of +/-1


* Kubernetes cluster kind:
EKS

**Additional context**
Medusa logs

$ kubectl logs prod-k8ssandra-dc1-us-east-1b-sts-0 -c medusa MEDUSA_MODE = GRPC sleeping for 0 sec Starting Medusa gRPC service /home/cassandra/.local/lib/python3.6/site-packages/requests/init.py:91: RequestsDependencyWarning: urllib3 (1.26.4) or chardet (3.0.4) doesn't match a supported version! RequestsDependencyWarning) INFO:root:Init service [2021-04-30 19:18:32,688] INFO: Init service DEBUG:root:Loading storage_provider: s3 [2021-04-30 19:18:32,688] DEBUG: Loading storage_provider: s3 DEBUG:root:Reading AWS credentials from /etc/medusa-secrets/medusa_s3_credentials [2021-04-30 19:18:32,689] DEBUG: Reading AWS credentials from /etc/medusa-secrets/medusa_s3_credentials DEBUG:urllib3.connectionpool:Starting new HTTPS connection (1): s3.amazonaws.com:443 [2021-04-30 19:18:33,061] DEBUG: Starting new HTTPS connection (1): s3.amazonaws.com:443 DEBUG:urllib3.connectionpool:https://s3.amazonaws.com:443 "HEAD /prod-k8ssandra2-s3-bucket HTTP/1.1" 200 0 [2021-04-30 19:18:33,103] DEBUG: https://s3.amazonaws.com:443 "HEAD /prod-k8ssandra2-s3-bucket HTTP/1.1" 200 0 INFO:root:Starting server. Listening on port 50051. [2021-04-30 19:18:33,453] INFO: Starting server. Listening on port 50051. INFO:root:Performing backup test [2021-04-30 19:25:45,382] INFO: Performing backup test INFO:root:Monitoring provider is noop [2021-04-30 19:25:45,383] INFO: Monitoring provider is noop DEBUG:root:Loading storage_provider: s3 [2021-04-30 19:25:45,383] DEBUG: Loading storage_provider: s3 DEBUG:root:Reading AWS credentials from /etc/medusa-secrets/medusa_s3_credentials [2021-04-30 19:25:45,383] DEBUG: Reading AWS credentials from /etc/medusa-secrets/medusa_s3_credentials DEBUG:urllib3.connectionpool:Starting new HTTPS connection (1): s3.amazonaws.com:443 [2021-04-30 19:25:45,725] DEBUG: Starting new HTTPS connection (1): s3.amazonaws.com:443 DEBUG:urllib3.connectionpool:https://s3.amazonaws.com:443 "HEAD /prod-k8ssandra2-s3-bucket HTTP/1.1" 200 0 [2021-04-30 19:25:45,800] DEBUG: https://s3.amazonaws.com:443 "HEAD /prod-k8ssandra2-s3-bucket HTTP/1.1" 200 0 DEBUG:root:This server has systemd: False [2021-04-30 19:25:46,152] DEBUG: This server has systemd: False WARNING:root:is ccm : 0 [2021-04-30 19:25:46,153] WARNING: is ccm : 0 DEBUG:root:Blob prod-k8ssandra-dc1-us-east-1b-sts-0.prod-k8ssandra-dc1-service.default.svc.cluster.local/test/meta/schema.cql was not found in cache. [2021-04-30 19:25:46,164] DEBUG: Blob prod-k8ssandra-dc1-us-east-1b-sts-0.prod-k8ssandra-dc1-service.default.svc.cluster.local/test/meta/schema.cql was not found in cache. DEBUG:root:[Storage] Getting object prod-k8ssandra-dc1-us-east-1b-sts-0.prod-k8ssandra-dc1-service.default.svc.cluster.local/test/meta/schema.cql [2021-04-30 19:25:46,164] DEBUG: [Storage] Getting object prod-k8ssandra-dc1-us-east-1b-sts-0.prod-k8ssandra-dc1-service.default.svc.cluster.local/test/meta/schema.cql DEBUG:urllib3.connectionpool:https://s3.amazonaws.com:443 "HEAD /prod-k8ssandra2-s3-bucket HTTP/1.1" 200 0 [2021-04-30 19:25:46,171] DEBUG: https://s3.amazonaws.com:443 "HEAD /prod-k8ssandra2-s3-bucket HTTP/1.1" 200 0 DEBUG:urllib3.connectionpool:https://s3.amazonaws.com:443 "HEAD /prod-k8ssandra2-s3-bucket/prod-k8ssandra-dc1-us-east-1b-sts-0.prod-k8ssandra-dc1-service.default.svc.cluster.local/test/meta/schema.cql HTTP/1.1" 404 0 [2021-04-30 19:25:46,193] DEBUG: https://s3.amazonaws.com:443 "HEAD /prod-k8ssandra2-s3-bucket/prod-k8ssandra-dc1-us-east-1b-sts-0.prod-k8ssandra-dc1-service.default.svc.cluster.local/test/meta/schema.cql HTTP/1.1" 404 0 DEBUG:root:Process psutil.Process(pid=1, name='python3', status='sleeping', started='19:18:32') was set to use only idle IO and CPU resources [2021-04-30 19:25:46,194] DEBUG: Process psutil.Process(pid=1, name='python3', status='sleeping', started='19:18:32') was set to use only idle IO and CPU resources INFO:root:Saving tokenmap and schema [2021-04-30 19:25:46,194] INFO: Saving tokenmap and schema DEBUG:cassandra.cluster:Connecting to cluster, contact points: ['10.0.2.189']; protocol version: 4 [2021-04-30 19:25:46,195] DEBUG: Connecting to cluster, contact points: ['10.0.2.189']; protocol version: 4 DEBUG:cassandra.pool:Host 10.0.2.189:9042 is now marked up [2021-04-30 19:25:46,195] DEBUG: Host 10.0.2.189:9042 is now marked up DEBUG:cassandra.cluster:[control connection] Opening new connection to 10.0.2.189:9042 [2021-04-30 19:25:46,196] DEBUG: [control connection] Opening new connection to 10.0.2.189:9042 DEBUG:cassandra.connection:Sending initial options message for new connection (140047656107200) to 10.0.2.189:9042 [2021-04-30 19:25:46,196] DEBUG: Sending initial options message for new connection (140047656107200) to 10.0.2.189:9042 DEBUG:cassandra.io.libevreactor:Starting libev event loop [2021-04-30 19:25:46,196] DEBUG: Starting libev event loop DEBUG:cassandra.connection:Received options response on new connection (140047656107200) from 10.0.2.189:9042 [2021-04-30 19:25:46,197] DEBUG: Received options response on new connection (140047656107200) from 10.0.2.189:9042 DEBUG:cassandra.connection:No available compression types supported on both ends. locally supported: odict_keys([]). remotely supported: ['snappy', 'lz4'] [2021-04-30 19:25:46,197] DEBUG: No available compression types supported on both ends. locally supported: odict_keys([]). remotely supported: ['snappy', 'lz4'] DEBUG:cassandra.connection:Sending StartupMessage on <LibevConnection(140047656107200) 10.0.2.189:9042> [2021-04-30 19:25:46,197] DEBUG: Sending StartupMessage on <LibevConnection(140047656107200) 10.0.2.189:9042> DEBUG:cassandra.connection:Sent StartupMessage on <LibevConnection(140047656107200) 10.0.2.189:9042> [2021-04-30 19:25:46,198] DEBUG: Sent StartupMessage on <LibevConnection(140047656107200) 10.0.2.189:9042> DEBUG:cassandra.connection:Got AuthenticateMessage on new connection (140047656107200) from 10.0.2.189:9042: org.apache.cassandra.auth.PasswordAuthenticator [2021-04-30 19:25:46,198] DEBUG: Got AuthenticateMessage on new connection (140047656107200) from 10.0.2.189:9042: org.apache.cassandra.auth.PasswordAuthenticator DEBUG:cassandra.connection:Sending SASL-based auth response on <LibevConnection(140047656107200) 10.0.2.189:9042> [2021-04-30 19:25:46,198] DEBUG: Sending SASL-based auth response on <LibevConnection(140047656107200) 10.0.2.189:9042> DEBUG:cassandra.connection:Connection <LibevConnection(140047656107200) 10.0.2.189:9042> successfully authenticated [2021-04-30 19:25:46,278] DEBUG: Connection <LibevConnection(140047656107200) 10.0.2.189:9042> successfully authenticated DEBUG:cassandra.cluster:[control connection] Established new connection <LibevConnection(140047656107200) 10.0.2.189:9042>, registering watchers and refreshing schema and topology [2021-04-30 19:25:46,278] DEBUG: [control connection] Established new connection <LibevConnection(140047656107200) 10.0.2.189:9042>, registering watchers and refreshing schema and topology DEBUG:cassandra.cluster:[control connection] Refreshing node list and token map using preloaded results [2021-04-30 19:25:46,284] DEBUG: [control connection] Refreshing node list and token map using preloaded results INFO:cassandra.policies:Using datacenter 'dc1' for DCAwareRoundRobinPolicy (via host '10.0.2.189:9042'); if incorrect, please specify a local_dc to the constructor, or limit contact points to local cluster nodes [2021-04-30 19:25:46,284] INFO: Using datacenter 'dc1' for DCAwareRoundRobinPolicy (via host '10.0.2.189:9042'); if incorrect, please specify a local_dc to the constructor, or limit contact points to local cluster nodes DEBUG:cassandra.cluster:[control connection] Found new host to connect to: 10.0.1.64:9042 [2021-04-30 19:25:46,284] DEBUG: [control connection] Found new host to connect to: 10.0.1.64:9042 INFO:cassandra.cluster:New Cassandra host <Host: 10.0.1.64:9042 dc1> discovered [2021-04-30 19:25:46,284] INFO: New Cassandra host <Host: 10.0.1.64:9042 dc1> discovered DEBUG:cassandra.cluster:Handling new host <Host: 10.0.1.64:9042 dc1> and notifying listeners [2021-04-30 19:25:46,284] DEBUG: Handling new host <Host: 10.0.1.64:9042 dc1> and notifying listeners DEBUG:cassandra.cluster:Done preparing queries for new host <Host: 10.0.1.64:9042 dc1> [2021-04-30 19:25:46,284] DEBUG: Done preparing queries for new host <Host: 10.0.1.64:9042 dc1> DEBUG:cassandra.pool:Host 10.0.1.64:9042 is now marked up [2021-04-30 19:25:46,284] DEBUG: Host 10.0.1.64:9042 is now marked up DEBUG:cassandra.cluster:[control connection] Found new host to connect to: 10.0.3.128:9042 [2021-04-30 19:25:46,285] DEBUG: [control connection] Found new host to connect to: 10.0.3.128:9042 INFO:cassandra.cluster:New Cassandra host <Host: 10.0.3.128:9042 dc1> discovered [2021-04-30 19:25:46,285] INFO: New Cassandra host <Host: 10.0.3.128:9042 dc1> discovered DEBUG:cassandra.cluster:Handling new host <Host: 10.0.3.128:9042 dc1> and notifying listeners [2021-04-30 19:25:46,285] DEBUG: Handling new host <Host: 10.0.3.128:9042 dc1> and notifying listeners DEBUG:cassandra.cluster:Done preparing queries for new host <Host: 10.0.3.128:9042 dc1> [2021-04-30 19:25:46,285] DEBUG: Done preparing queries for new host <Host: 10.0.3.128:9042 dc1> DEBUG:cassandra.pool:Host 10.0.3.128:9042 is now marked up [2021-04-30 19:25:46,285] DEBUG: Host 10.0.3.128:9042 is now marked up DEBUG:cassandra.cluster:[control connection] Finished fetching ring info [2021-04-30 19:25:46,285] DEBUG: [control connection] Finished fetching ring info DEBUG:cassandra.cluster:[control connection] Rebuilding token map due to topology changes [2021-04-30 19:25:46,285] DEBUG: [control connection] Rebuilding token map due to topology changes DEBUG:cassandra.cluster:Control connection created [2021-04-30 19:25:46,297] DEBUG: Control connection created DEBUG:cassandra.pool:Initializing connection for host 10.0.2.189:9042 [2021-04-30 19:25:46,298] DEBUG: Initializing connection for host 10.0.2.189:9042 DEBUG:cassandra.pool:Initializing connection for host 10.0.1.64:9042 [2021-04-30 19:25:46,298] DEBUG: Initializing connection for host 10.0.1.64:9042 DEBUG:cassandra.connection:Sending initial options message for new connection (140047656034992) to 10.0.2.189:9042 [2021-04-30 19:25:46,299] DEBUG: Sending initial options message for new connection (140047656034992) to 10.0.2.189:9042 DEBUG:cassandra.connection:Received options response on new connection (140047656034992) from 10.0.2.189:9042 [2021-04-30 19:25:46,300] DEBUG: Received options response on new connection (140047656034992) from 10.0.2.189:9042 DEBUG:cassandra.connection:Sending initial options message for new connection (140047616862584) to 10.0.1.64:9042 [2021-04-30 19:25:46,300] DEBUG: Sending initial options message for new connection (140047616862584) to 10.0.1.64:9042 DEBUG:cassandra.connection:No available compression types supported on both ends. locally supported: odict_keys([]). remotely supported: ['snappy', 'lz4'] [2021-04-30 19:25:46,300] DEBUG: No available compression types supported on both ends. locally supported: odict_keys([]). remotely supported: ['snappy', 'lz4'] DEBUG:cassandra.connection:Sending StartupMessage on <LibevConnection(140047656034992) 10.0.2.189:9042> [2021-04-30 19:25:46,300] DEBUG: Sending StartupMessage on <LibevConnection(140047656034992) 10.0.2.189:9042> DEBUG:cassandra.connection:Sent StartupMessage on <LibevConnection(140047656034992) 10.0.2.189:9042> [2021-04-30 19:25:46,301] DEBUG: Sent StartupMessage on <LibevConnection(140047656034992) 10.0.2.189:9042> DEBUG:cassandra.connection:Got AuthenticateMessage on new connection (140047656034992) from 10.0.2.189:9042: org.apache.cassandra.auth.PasswordAuthenticator [2021-04-30 19:25:46,301] DEBUG: Got AuthenticateMessage on new connection (140047656034992) from 10.0.2.189:9042: org.apache.cassandra.auth.PasswordAuthenticator DEBUG:cassandra.connection:Sending SASL-based auth response on <LibevConnection(140047656034992) 10.0.2.189:9042> [2021-04-30 19:25:46,301] DEBUG: Sending SASL-based auth response on <LibevConnection(140047656034992) 10.0.2.189:9042> DEBUG:cassandra.connection:Received options response on new connection (140047616862584) from 10.0.1.64:9042 [2021-04-30 19:25:46,302] DEBUG: Received options response on new connection (140047616862584) from 10.0.1.64:9042 DEBUG:cassandra.connection:No available compression types supported on both ends. locally supported: odict_keys([]). remotely supported: ['snappy', 'lz4'] [2021-04-30 19:25:46,302] DEBUG: No available compression types supported on both ends. locally supported: odict_keys([]). remotely supported: ['snappy', 'lz4'] DEBUG:cassandra.connection:Sending StartupMessage on <LibevConnection(140047616862584) 10.0.1.64:9042> [2021-04-30 19:25:46,302] DEBUG: Sending StartupMessage on <LibevConnection(140047616862584) 10.0.1.64:9042> DEBUG:cassandra.connection:Sent StartupMessage on <LibevConnection(140047616862584) 10.0.1.64:9042> [2021-04-30 19:25:46,302] DEBUG: Sent StartupMessage on <LibevConnection(140047616862584) 10.0.1.64:9042> DEBUG:cassandra.connection:Got AuthenticateMessage on new connection (140047616862584) from 10.0.1.64:9042: org.apache.cassandra.auth.PasswordAuthenticator [2021-04-30 19:25:46,303] DEBUG: Got AuthenticateMessage on new connection (140047616862584) from 10.0.1.64:9042: org.apache.cassandra.auth.PasswordAuthenticator DEBUG:cassandra.connection:Sending SASL-based auth response on <LibevConnection(140047616862584) 10.0.1.64:9042> [2021-04-30 19:25:46,304] DEBUG: Sending SASL-based auth response on <LibevConnection(140047616862584) 10.0.1.64:9042> DEBUG:cassandra.connection:Connection <LibevConnection(140047656034992) 10.0.2.189:9042> successfully authenticated [2021-04-30 19:25:46,382] DEBUG: Connection <LibevConnection(140047656034992) 10.0.2.189:9042> successfully authenticated DEBUG:cassandra.pool:Finished initializing connection for host 10.0.2.189:9042 [2021-04-30 19:25:46,382] DEBUG: Finished initializing connection for host 10.0.2.189:9042 DEBUG:cassandra.cluster:Added pool for host 10.0.2.189:9042 to session [2021-04-30 19:25:46,382] DEBUG: Added pool for host 10.0.2.189:9042 to session DEBUG:cassandra.pool:Initializing connection for host 10.0.3.128:9042 [2021-04-30 19:25:46,382] DEBUG: Initializing connection for host 10.0.3.128:9042 DEBUG:cassandra.connection:Sending initial options message for new connection (140047616863984) to 10.0.3.128:9042 [2021-04-30 19:25:46,384] DEBUG: Sending initial options message for new connection (140047616863984) to 10.0.3.128:9042 DEBUG:cassandra.connection:Received options response on new connection (140047616863984) from 10.0.3.128:9042 [2021-04-30 19:25:46,385] DEBUG: Received options response on new connection (140047616863984) from 10.0.3.128:9042 DEBUG:cassandra.connection:No available compression types supported on both ends. locally supported: odict_keys([]). remotely supported: ['snappy', 'lz4'] [2021-04-30 19:25:46,385] DEBUG: No available compression types supported on both ends. locally supported: odict_keys([]). remotely supported: ['snappy', 'lz4'] DEBUG:cassandra.connection:Sending StartupMessage on <LibevConnection(140047616863984) 10.0.3.128:9042> [2021-04-30 19:25:46,385] DEBUG: Sending StartupMessage on <LibevConnection(140047616863984) 10.0.3.128:9042> DEBUG:cassandra.connection:Sent StartupMessage on <LibevConnection(140047616863984) 10.0.3.128:9042> [2021-04-30 19:25:46,385] DEBUG: Sent StartupMessage on <LibevConnection(140047616863984) 10.0.3.128:9042> DEBUG:cassandra.connection:Got AuthenticateMessage on new connection (140047616863984) from 10.0.3.128:9042: org.apache.cassandra.auth.PasswordAuthenticator [2021-04-30 19:25:46,387] DEBUG: Got AuthenticateMessage on new connection (140047616863984) from 10.0.3.128:9042: org.apache.cassandra.auth.PasswordAuthenticator DEBUG:cassandra.connection:Sending SASL-based auth response on <LibevConnection(140047616863984) 10.0.3.128:9042> [2021-04-30 19:25:46,387] DEBUG: Sending SASL-based auth response on <LibevConnection(140047616863984) 10.0.3.128:9042> DEBUG:cassandra.connection:Connection <LibevConnection(140047616862584) 10.0.1.64:9042> successfully authenticated [2021-04-30 19:25:46,389] DEBUG: Connection <LibevConnection(140047616862584) 10.0.1.64:9042> successfully authenticated DEBUG:cassandra.pool:Finished initializing connection for host 10.0.1.64:9042 [2021-04-30 19:25:46,389] DEBUG: Finished initializing connection for host 10.0.1.64:9042 DEBUG:cassandra.cluster:Added pool for host 10.0.1.64:9042 to session [2021-04-30 19:25:46,389] DEBUG: Added pool for host 10.0.1.64:9042 to session DEBUG:cassandra.connection:Connection <LibevConnection(140047616863984) 10.0.3.128:9042> successfully authenticated [2021-04-30 19:25:46,471] DEBUG: Connection <LibevConnection(140047616863984) 10.0.3.128:9042> successfully authenticated DEBUG:cassandra.pool:Finished initializing connection for host 10.0.3.128:9042 [2021-04-30 19:25:46,471] DEBUG: Finished initializing connection for host 10.0.3.128:9042 DEBUG:cassandra.cluster:Added pool for host 10.0.3.128:9042 to session [2021-04-30 19:25:46,471] DEBUG: Added pool for host 10.0.3.128:9042 to session DEBUG:cassandra.cluster:Not starting MonitorReporter thread for Insights; not supported by server version 3.11.10 on ControlConnection host 10.0.2.189:9042 [2021-04-30 19:25:46,471] DEBUG: Not starting MonitorReporter thread for Insights; not supported by server version 3.11.10 on ControlConnection host 10.0.2.189:9042 DEBUG:cassandra.cluster:Started Session with client_id 2f1315fa-6d59-4882-a15a-f870fccdb75d and session_id dce52b2e-32d1-4cf2-acd7-9c504289e01e [2021-04-30 19:25:46,471] DEBUG: Started Session with client_id 2f1315fa-6d59-4882-a15a-f870fccdb75d and session_id dce52b2e-32d1-4cf2-acd7-9c504289e01e DEBUG:root:Checking datacenter... [2021-04-30 19:25:46,474] DEBUG: Checking datacenter... DEBUG:root:Resolved 10.0.2.189 to prod-k8ssandra-dc1-us-east-1b-sts-0.prod-k8ssandra-dc1-service.default.svc.cluster.local [2021-04-30 19:25:46,475] DEBUG: Resolved 10.0.2.189 to prod-k8ssandra-dc1-us-east-1b-sts-0.prod-k8ssandra-dc1-service.default.svc.cluster.local DEBUG:root:Checking host 10.0.2.189 against 10.0.2.189/prod-k8ssandra-dc1-us-east-1b-sts-0.prod-k8ssandra-dc1-service.default.svc.cluster.local [2021-04-30 19:25:46,475] DEBUG: Checking host 10.0.2.189 against 10.0.2.189/prod-k8ssandra-dc1-us-east-1b-sts-0.prod-k8ssandra-dc1-service.default.svc.cluster.local DEBUG:root:Resolved 10.0.1.64 to 10-0-1-64.prod-k8ssandra-dc1-all-pods-service.default.svc.cluster.local [2021-04-30 19:25:46,477] DEBUG: Resolved 10.0.1.64 to 10-0-1-64.prod-k8ssandra-dc1-all-pods-service.default.svc.cluster.local DEBUG:root:Resolved 10.0.2.189 to prod-k8ssandra-dc1-us-east-1b-sts-0.prod-k8ssandra-dc1-service.default.svc.cluster.local [2021-04-30 19:25:46,477] DEBUG: Resolved 10.0.2.189 to prod-k8ssandra-dc1-us-east-1b-sts-0.prod-k8ssandra-dc1-service.default.svc.cluster.local DEBUG:root:Resolved 10.0.3.128 to 10-0-3-128.prod-k8ssandra-dc1-all-pods-service.default.svc.cluster.local [2021-04-30 19:25:46,477] DEBUG: Resolved 10.0.3.128 to 10-0-3-128.prod-k8ssandra-dc1-all-pods-service.default.svc.cluster.local DEBUG:cassandra.io.libevreactor:Closing connection (140047656034992) to 10.0.2.189:9042 [2021-04-30 19:25:46,477] DEBUG: Closing connection (140047656034992) to 10.0.2.189:9042 DEBUG:cassandra.io.libevreactor:Closed socket to 10.0.2.189:9042 [2021-04-30 19:25:46,477] DEBUG: Closed socket to 10.0.2.189:9042 DEBUG:cassandra.io.libevreactor:Closing connection (140047616862584) to 10.0.1.64:9042 [2021-04-30 19:25:46,477] DEBUG: Closing connection (140047616862584) to 10.0.1.64:9042 DEBUG:cassandra.io.libevreactor:Closed socket to 10.0.1.64:9042 [2021-04-30 19:25:46,478] DEBUG: Closed socket to 10.0.1.64:9042 DEBUG:cassandra.io.libevreactor:Closing connection (140047616863984) to 10.0.3.128:9042 [2021-04-30 19:25:46,478] DEBUG: Closing connection (140047616863984) to 10.0.3.128:9042 DEBUG:cassandra.io.libevreactor:Closed socket to 10.0.3.128:9042 [2021-04-30 19:25:46,478] DEBUG: Closed socket to 10.0.3.128:9042 DEBUG:cassandra.cluster:Shutting down Cluster Scheduler [2021-04-30 19:25:46,478] DEBUG: Shutting down Cluster Scheduler DEBUG:cassandra.cluster:Shutting down control connection [2021-04-30 19:25:46,478] DEBUG: Shutting down control connection DEBUG:cassandra.io.libevreactor:Closing connection (140047656107200) to 10.0.2.189:9042 [2021-04-30 19:25:46,478] DEBUG: Closing connection (140047656107200) to 10.0.2.189:9042 DEBUG:cassandra.io.libevreactor:Closed socket to 10.0.2.189:9042 [2021-04-30 19:25:46,478] DEBUG: Closed socket to 10.0.2.189:9042 DEBUG:cassandra.io.libevreactor:All Connections currently closed, event loop ended [2021-04-30 19:25:46,478] DEBUG: All Connections currently closed, event loop ended DEBUG:urllib3.connectionpool:https://s3.amazonaws.com:443 "POST /prod-k8ssandra2-s3-bucket/prod-k8ssandra-dc1-us-east-1b-sts-0.prod-k8ssandra-dc1-service.default.svc.cluster.local/test/meta/schema.cql?uploads= HTTP/1.1" 403 None [2021-04-30 19:25:46,592] DEBUG: https://s3.amazonaws.com:443 "POST /prod-k8ssandra2-s3-bucket/prod-k8ssandra-dc1-us-east-1b-sts-0.prod-k8ssandra-dc1-service.default.svc.cluster.local/test/meta/schema.cql?uploads= HTTP/1.1" 403 None DEBUG:urllib3.connectionpool:Resetting dropped connection: s3.amazonaws.com [2021-04-30 19:26:06,609] DEBUG: Resetting dropped connection: s3.amazonaws.com DEBUG:urllib3.connectionpool:https://s3.amazonaws.com:443 "POST /prod-k8ssandra2-s3-bucket/prod-k8ssandra-dc1-us-east-1b-sts-0.prod-k8ssandra-dc1-service.default.svc.cluster.local/test/meta/schema.cql?uploads= HTTP/1.1" 403 None [2021-04-30 19:26:06,665] DEBUG: https://s3.amazonaws.com:443 "POST /prod-k8ssandra2-s3-bucket/prod-k8ssandra-dc1-us-east-1b-sts-0.prod-k8ssandra-dc1-service.default.svc.cluster.local/test/meta/schema.cql?uploads= HTTP/1.1" 403 None DEBUG:urllib3.connectionpool:Resetting dropped connection: s3.amazonaws.com [2021-04-30 19:26:46,705] DEBUG: Resetting dropped connection: s3.amazonaws.com DEBUG:urllib3.connectionpool:https://s3.amazonaws.com:443 "POST /prod-k8ssandra2-s3-bucket/prod-k8ssandra-dc1-us-east-1b-sts-0.prod-k8ssandra-dc1-service.default.svc.cluster.local/test/meta/schema.cql?uploads= HTTP/1.1" 403 None [2021-04-30 19:26:46,762] DEBUG: https://s3.amazonaws.com:443 "POST /prod-k8ssandra2-s3-bucket/prod-k8ssandra-dc1-us-east-1b-sts-0.prod-k8ssandra-dc1-service.default.svc.cluster.local/test/meta/schema.cql?uploads= HTTP/1.1" 403 None DEBUG:urllib3.connectionpool:Resetting dropped connection: s3.amazonaws.com [2021-04-30 19:28:06,844] DEBUG: Resetting dropped connection: s3.amazonaws.com DEBUG:urllib3.connectionpool:https://s3.amazonaws.com:443 "POST /prod-k8ssandra2-s3-bucket/prod-k8ssandra-dc1-us-east-1b-sts-0.prod-k8ssandra-dc1-service.default.svc.cluster.local/test/meta/schema.cql?uploads= HTTP/1.1" 403 None [2021-04-30 19:28:06,898] DEBUG: https://s3.amazonaws.com:443 "POST /prod-k8ssandra2-s3-bucket/prod-k8ssandra-dc1-us-east-1b-sts-0.prod-k8ssandra-dc1-service.default.svc.cluster.local/test/meta/schema.cql?uploads= HTTP/1.1" 403 None DEBUG:urllib3.connectionpool:Resetting dropped connection: s3.amazonaws.com [2021-04-30 19:30:06,991] DEBUG: Resetting dropped connection: s3.amazonaws.com DEBUG:urllib3.connectionpool:https://s3.amazonaws.com:443 "POST /prod-k8ssandra2-s3-bucket/prod-k8ssandra-dc1-us-east-1b-sts-0.prod-k8ssandra-dc1-service.default.svc.cluster.local/test/meta/schema.cql?uploads= HTTP/1.1" 403 None [2021-04-30 19:30:07,050] DEBUG: https://s3.amazonaws.com:443 "POST /prod-k8ssandra2-s3-bucket/prod-k8ssandra-dc1-us-east-1b-sts-0.prod-k8ssandra-dc1-service.default.svc.cluster.local/test/meta/schema.cql?uploads= HTTP/1.1" 403 None DEBUG:urllib3.connectionpool:Resetting dropped connection: s3.amazonaws.com [2021-04-30 19:32:07,136] DEBUG: Resetting dropped connection: s3.amazonaws.com DEBUG:urllib3.connectionpool:https://s3.amazonaws.com:443 "POST /prod-k8ssandra2-s3-bucket/prod-k8ssandra-dc1-us-east-1b-sts-0.prod-k8ssandra-dc1-service.default.svc.cluster.local/test/meta/schema.cql?uploads= HTTP/1.1" 403 None [2021-04-30 19:32:07,212] DEBUG: https://s3.amazonaws.com:443 "POST /prod-k8ssandra2-s3-bucket/prod-k8ssandra-dc1-us-east-1b-sts-0.prod-k8ssandra-dc1-service.default.svc.cluster.local/test/meta/schema.cql?uploads= HTTP/1.1" 403 None INFO:root:Performing backup test [2021-04-30 19:33:40,258] INFO: Performing backup test INFO:root:Monitoring provider is noop [2021-04-30 19:33:40,258] INFO: Monitoring provider is noop DEBUG:root:Loading storage_provider: s3 [2021-04-30 19:33:40,258] DEBUG: Loading storage_provider: s3 DEBUG:root:Reading AWS credentials from /etc/medusa-secrets/medusa_s3_credentials [2021-04-30 19:33:40,259] DEBUG: Reading AWS credentials from /etc/medusa-secrets/medusa_s3_credentials DEBUG:urllib3.connectionpool:Starting new HTTPS connection (1): s3.amazonaws.com:443 [2021-04-30 19:33:40,600] DEBUG: Starting new HTTPS connection (1): s3.amazonaws.com:443 DEBUG:urllib3.connectionpool:https://s3.amazonaws.com:443 "HEAD /prod-k8ssandra2-s3-bucket HTTP/1.1" 200 0 [2021-04-30 19:33:40,693] DEBUG: https://s3.amazonaws.com:443 "HEAD /prod-k8ssandra2-s3-bucket HTTP/1.1" 200 0 DEBUG:root:This server has systemd: False [2021-04-30 19:33:41,028] DEBUG: This server has systemd: False WARNING:root:is ccm : 0 [2021-04-30 19:33:41,029] WARNING: is ccm : 0 DEBUG:root:Blob prod-k8ssandra-dc1-us-east-1b-sts-0.prod-k8ssandra-dc1-service.default.svc.cluster.local/test/meta/schema.cql was not found in cache. [2021-04-30 19:33:41,040] DEBUG: Blob prod-k8ssandra-dc1-us-east-1b-sts-0.prod-k8ssandra-dc1-service.default.svc.cluster.local/test/meta/schema.cql was not found in cache. DEBUG:root:[Storage] Getting object prod-k8ssandra-dc1-us-east-1b-sts-0.prod-k8ssandra-dc1-service.default.svc.cluster.local/test/meta/schema.cql [2021-04-30 19:33:41,040] DEBUG: [Storage] Getting object prod-k8ssandra-dc1-us-east-1b-sts-0.prod-k8ssandra-dc1-service.default.svc.cluster.local/test/meta/schema.cql DEBUG:urllib3.connectionpool:https://s3.amazonaws.com:443 "HEAD /prod-k8ssandra2-s3-bucket HTTP/1.1" 200 0 [2021-04-30 19:33:41,046] DEBUG: https://s3.amazonaws.com:443 "HEAD /prod-k8ssandra2-s3-bucket HTTP/1.1" 200 0 DEBUG:urllib3.connectionpool:https://s3.amazonaws.com:443 "HEAD /prod-k8ssandra2-s3-bucket/prod-k8ssandra-dc1-us-east-1b-sts-0.prod-k8ssandra-dc1-service.default.svc.cluster.local/test/meta/schema.cql HTTP/1.1" 404 0 [2021-04-30 19:33:41,087] DEBUG: https://s3.amazonaws.com:443 "HEAD /prod-k8ssandra2-s3-bucket/prod-k8ssandra-dc1-us-east-1b-sts-0.prod-k8ssandra-dc1-service.default.svc.cluster.local/test/meta/schema.cql HTTP/1.1" 404 0 DEBUG:root:Process psutil.Process(pid=1, name='python3', status='sleeping', started='19:18:32') was set to use only idle IO and CPU resources [2021-04-30 19:33:41,088] DEBUG: Process psutil.Process(pid=1, name='python3', status='sleeping', started='19:18:32') was set to use only idle IO and CPU resources INFO:root:Saving tokenmap and schema [2021-04-30 19:33:41,088] INFO: Saving tokenmap and schema DEBUG:cassandra.cluster:Connecting to cluster, contact points: ['10.0.2.189']; protocol version: 4 [2021-04-30 19:33:41,088] DEBUG: Connecting to cluster, contact points: ['10.0.2.189']; protocol version: 4 DEBUG:cassandra.pool:Host 10.0.2.189:9042 is now marked up [2021-04-30 19:33:41,089] DEBUG: Host 10.0.2.189:9042 is now marked up DEBUG:cassandra.cluster:[control connection] Opening new connection to 10.0.2.189:9042 [2021-04-30 19:33:41,089] DEBUG: [control connection] Opening new connection to 10.0.2.189:9042 DEBUG:cassandra.connection:Sending initial options message for new connection (140047616713896) to 10.0.2.189:9042 [2021-04-30 19:33:41,089] DEBUG: Sending initial options message for new connection (140047616713896) to 10.0.2.189:9042 DEBUG:cassandra.io.libevreactor:Starting libev event loop [2021-04-30 19:33:41,089] DEBUG: Starting libev event loop DEBUG:cassandra.connection:Received options response on new connection (140047616713896) from 10.0.2.189:9042 [2021-04-30 19:33:41,090] DEBUG: Received options response on new connection (140047616713896) from 10.0.2.189:9042 DEBUG:cassandra.connection:No available compression types supported on both ends. locally supported: odict_keys([]). remotely supported: ['snappy', 'lz4'] [2021-04-30 19:33:41,090] DEBUG: No available compression types supported on both ends. locally supported: odict_keys([]). remotely supported: ['snappy', 'lz4'] DEBUG:cassandra.connection:Sending StartupMessage on <LibevConnection(140047616713896) 10.0.2.189:9042> [2021-04-30 19:33:41,090] DEBUG: Sending StartupMessage on <LibevConnection(140047616713896) 10.0.2.189:9042> DEBUG:cassandra.connection:Sent StartupMessage on <LibevConnection(140047616713896) 10.0.2.189:9042> [2021-04-30 19:33:41,090] DEBUG: Sent StartupMessage on <LibevConnection(140047616713896) 10.0.2.189:9042> DEBUG:cassandra.connection:Got AuthenticateMessage on new connection (140047616713896) from 10.0.2.189:9042: org.apache.cassandra.auth.PasswordAuthenticator [2021-04-30 19:33:41,091] DEBUG: Got AuthenticateMessage on new connection (140047616713896) from 10.0.2.189:9042: org.apache.cassandra.auth.PasswordAuthenticator DEBUG:cassandra.connection:Sending SASL-based auth response on <LibevConnection(140047616713896) 10.0.2.189:9042> [2021-04-30 19:33:41,091] DEBUG: Sending SASL-based auth response on <LibevConnection(140047616713896) 10.0.2.189:9042> DEBUG:cassandra.connection:Connection <LibevConnection(140047616713896) 10.0.2.189:9042> successfully authenticated [2021-04-30 19:33:41,171] DEBUG: Connection <LibevConnection(140047616713896) 10.0.2.189:9042> successfully authenticated DEBUG:cassandra.cluster:[control connection] Established new connection <LibevConnection(140047616713896) 10.0.2.189:9042>, registering watchers and refreshing schema and topology [2021-04-30 19:33:41,171] DEBUG: [control connection] Established new connection <LibevConnection(140047616713896) 10.0.2.189:9042>, registering watchers and refreshing schema and topology DEBUG:cassandra.cluster:[control connection] Refreshing node list and token map using preloaded results [2021-04-30 19:33:41,176] DEBUG: [control connection] Refreshing node list and token map using preloaded results INFO:cassandra.policies:Using datacenter 'dc1' for DCAwareRoundRobinPolicy (via host '10.0.2.189:9042'); if incorrect, please specify a local_dc to the constructor, or limit contact points to local cluster nodes [2021-04-30 19:33:41,176] INFO: Using datacenter 'dc1' for DCAwareRoundRobinPolicy (via host '10.0.2.189:9042'); if incorrect, please specify a local_dc to the constructor, or limit contact points to local cluster nodes DEBUG:cassandra.cluster:[control connection] Found new host to connect to: 10.0.1.64:9042 [2021-04-30 19:33:41,177] DEBUG: [control connection] Found new host to connect to: 10.0.1.64:9042 INFO:cassandra.cluster:New Cassandra host <Host: 10.0.1.64:9042 dc1> discovered [2021-04-30 19:33:41,177] INFO: New Cassandra host <Host: 10.0.1.64:9042 dc1> discovered DEBUG:cassandra.cluster:Handling new host <Host: 10.0.1.64:9042 dc1> and notifying listeners [2021-04-30 19:33:41,177] DEBUG: Handling new host <Host: 10.0.1.64:9042 dc1> and notifying listeners DEBUG:cassandra.cluster:Done preparing queries for new host <Host: 10.0.1.64:9042 dc1> [2021-04-30 19:33:41,177] DEBUG: Done preparing queries for new host <Host: 10.0.1.64:9042 dc1> DEBUG:cassandra.pool:Host 10.0.1.64:9042 is now marked up [2021-04-30 19:33:41,177] DEBUG: Host 10.0.1.64:9042 is now marked up DEBUG:cassandra.cluster:[control connection] Found new host to connect to: 10.0.3.128:9042 [2021-04-30 19:33:41,177] DEBUG: [control connection] Found new host to connect to: 10.0.3.128:9042 INFO:cassandra.cluster:New Cassandra host <Host: 10.0.3.128:9042 dc1> discovered [2021-04-30 19:33:41,177] INFO: New Cassandra host <Host: 10.0.3.128:9042 dc1> discovered DEBUG:cassandra.cluster:Handling new host <Host: 10.0.3.128:9042 dc1> and notifying listeners [2021-04-30 19:33:41,177] DEBUG: Handling new host <Host: 10.0.3.128:9042 dc1> and notifying listeners DEBUG:cassandra.cluster:Done preparing queries for new host <Host: 10.0.3.128:9042 dc1> [2021-04-30 19:33:41,177] DEBUG: Done preparing queries for new host <Host: 10.0.3.128:9042 dc1> DEBUG:cassandra.pool:Host 10.0.3.128:9042 is now marked up [2021-04-30 19:33:41,177] DEBUG: Host 10.0.3.128:9042 is now marked up DEBUG:cassandra.cluster:[control connection] Finished fetching ring info [2021-04-30 19:33:41,177] DEBUG: [control connection] Finished fetching ring info DEBUG:cassandra.cluster:[control connection] Rebuilding token map due to topology changes [2021-04-30 19:33:41,177] DEBUG: [control connection] Rebuilding token map due to topology changes DEBUG:cassandra.cluster:Control connection created [2021-04-30 19:33:41,193] DEBUG: Control connection created DEBUG:cassandra.pool:Initializing connection for host 10.0.2.189:9042 [2021-04-30 19:33:41,194] DEBUG: Initializing connection for host 10.0.2.189:9042 DEBUG:cassandra.pool:Initializing connection for host 10.0.1.64:9042 [2021-04-30 19:33:41,194] DEBUG: Initializing connection for host 10.0.1.64:9042 DEBUG:cassandra.connection:Sending initial options message for new connection (140047616714960) to 10.0.2.189:9042 [2021-04-30 19:33:41,195] DEBUG: Sending initial options message for new connection (140047616714960) to 10.0.2.189:9042 DEBUG:cassandra.connection:Received options response on new connection (140047616714960) from 10.0.2.189:9042 [2021-04-30 19:33:41,196] DEBUG: Received options response on new connection (140047616714960) from 10.0.2.189:9042 DEBUG:cassandra.connection:No available compression types supported on both ends. locally supported: odict_keys([]). remotely supported: ['snappy', 'lz4'] [2021-04-30 19:33:41,196] DEBUG: No available compression types supported on both ends. locally supported: odict_keys([]). remotely supported: ['snappy', 'lz4'] DEBUG:cassandra.connection:Sending StartupMessage on <LibevConnection(140047616714960) 10.0.2.189:9042> [2021-04-30 19:33:41,196] DEBUG: Sending StartupMessage on <LibevConnection(140047616714960) 10.0.2.189:9042> DEBUG:cassandra.connection:Sent StartupMessage on <LibevConnection(140047616714960) 10.0.2.189:9042> [2021-04-30 19:33:41,196] DEBUG: Sent StartupMessage on <LibevConnection(140047616714960) 10.0.2.189:9042> DEBUG:cassandra.connection:Sending initial options message for new connection (140047615680584) to 10.0.1.64:9042 [2021-04-30 19:33:41,196] DEBUG: Sending initial options message for new connection (140047615680584) to 10.0.1.64:9042 DEBUG:cassandra.connection:Got AuthenticateMessage on new connection (140047616714960) from 10.0.2.189:9042: org.apache.cassandra.auth.PasswordAuthenticator [2021-04-30 19:33:41,197] DEBUG: Got AuthenticateMessage on new connection (140047616714960) from 10.0.2.189:9042: org.apache.cassandra.auth.PasswordAuthenticator DEBUG:cassandra.connection:Sending SASL-based auth response on <LibevConnection(140047616714960) 10.0.2.189:9042> [2021-04-30 19:33:41,197] DEBUG: Sending SASL-based auth response on <LibevConnection(140047616714960) 10.0.2.189:9042> DEBUG:cassandra.connection:Received options response on new connection (140047615680584) from 10.0.1.64:9042 [2021-04-30 19:33:41,198] DEBUG: Received options response on new connection (140047615680584) from 10.0.1.64:9042 DEBUG:cassandra.connection:No available compression types supported on both ends. locally supported: odict_keys([]). remotely supported: ['snappy', 'lz4'] [2021-04-30 19:33:41,199] DEBUG: No available compression types supported on both ends. locally supported: odict_keys([]). remotely supported: ['snappy', 'lz4'] DEBUG:cassandra.connection:Sending StartupMessage on <LibevConnection(140047615680584) 10.0.1.64:9042> [2021-04-30 19:33:41,199] DEBUG: Sending StartupMessage on <LibevConnection(140047615680584) 10.0.1.64:9042> DEBUG:cassandra.connection:Sent StartupMessage on <LibevConnection(140047615680584) 10.0.1.64:9042> [2021-04-30 19:33:41,199] DEBUG: Sent StartupMessage on <LibevConnection(140047615680584) 10.0.1.64:9042> DEBUG:cassandra.connection:Got AuthenticateMessage on new connection (140047615680584) from 10.0.1.64:9042: org.apache.cassandra.auth.PasswordAuthenticator [2021-04-30 19:33:41,200] DEBUG: Got AuthenticateMessage on new connection (140047615680584) from 10.0.1.64:9042: org.apache.cassandra.auth.PasswordAuthenticator DEBUG:cassandra.connection:Sending SASL-based auth response on <LibevConnection(140047615680584) 10.0.1.64:9042> [2021-04-30 19:33:41,200] DEBUG: Sending SASL-based auth response on <LibevConnection(140047615680584) 10.0.1.64:9042> DEBUG:cassandra.connection:Connection <LibevConnection(140047616714960) 10.0.2.189:9042> successfully authenticated [2021-04-30 19:33:41,277] DEBUG: Connection <LibevConnection(140047616714960) 10.0.2.189:9042> successfully authenticated DEBUG:cassandra.pool:Finished initializing connection for host 10.0.2.189:9042 [2021-04-30 19:33:41,277] DEBUG: Finished initializing connection for host 10.0.2.189:9042 DEBUG:cassandra.cluster:Added pool for host 10.0.2.189:9042 to session [2021-04-30 19:33:41,277] DEBUG: Added pool for host 10.0.2.189:9042 to session DEBUG:cassandra.pool:Initializing connection for host 10.0.3.128:9042 [2021-04-30 19:33:41,277] DEBUG: Initializing connection for host 10.0.3.128:9042 DEBUG:cassandra.cluster:Not starting MonitorReporter thread for Insights; not supported by server version 3.11.10 on ControlConnection host 10.0.2.189:9042 [2021-04-30 19:33:41,277] DEBUG: Not starting MonitorReporter thread for Insights; not supported by server version 3.11.10 on ControlConnection host 10.0.2.189:9042 DEBUG:cassandra.cluster:Started Session with client_id 360cac2f-94b6-4450-8ce8-a3b91ff5f330 and session_id f22a4a5f-bef4-4d4c-b693-885ac3662515 [2021-04-30 19:33:41,278] DEBUG: Started Session with client_id 360cac2f-94b6-4450-8ce8-a3b91ff5f330 and session_id f22a4a5f-bef4-4d4c-b693-885ac3662515 DEBUG:root:Checking datacenter... [2021-04-30 19:33:41,281] DEBUG: Checking datacenter... DEBUG:cassandra.connection:Sending initial options message for new connection (140047615677608) to 10.0.3.128:9042 [2021-04-30 19:33:41,281] DEBUG: Sending initial options message for new connection (140047615677608) to 10.0.3.128:9042 DEBUG:root:Resolved 10.0.2.189 to prod-k8ssandra-dc1-us-east-1b-sts-0.prod-k8ssandra-dc1-service.default.svc.cluster.local [2021-04-30 19:33:41,282] DEBUG: Resolved 10.0.2.189 to prod-k8ssandra-dc1-us-east-1b-sts-0.prod-k8ssandra-dc1-service.default.svc.cluster.local DEBUG:root:Checking host 10.0.2.189 against 10.0.2.189/prod-k8ssandra-dc1-us-east-1b-sts-0.prod-k8ssandra-dc1-service.default.svc.cluster.local [2021-04-30 19:33:41,282] DEBUG: Checking host 10.0.2.189 against 10.0.2.189/prod-k8ssandra-dc1-us-east-1b-sts-0.prod-k8ssandra-dc1-service.default.svc.cluster.local DEBUG:cassandra.connection:Connection <LibevConnection(140047615680584) 10.0.1.64:9042> successfully authenticated [2021-04-30 19:33:41,282] DEBUG: Connection <LibevConnection(140047615680584) 10.0.1.64:9042> successfully authenticated DEBUG:cassandra.pool:Finished initializing connection for host 10.0.1.64:9042 [2021-04-30 19:33:41,283] DEBUG: Finished initializing connection for host 10.0.1.64:9042 DEBUG:cassandra.connection:Received options response on new connection (140047615677608) from 10.0.3.128:9042 [2021-04-30 19:33:41,283] DEBUG: Received options response on new connection (140047615677608) from 10.0.3.128:9042 DEBUG:cassandra.cluster:Added pool for host 10.0.1.64:9042 to session [2021-04-30 19:33:41,283] DEBUG: Added pool for host 10.0.1.64:9042 to session DEBUG:cassandra.connection:No available compression types supported on both ends. locally supported: odict_keys([]). remotely supported: ['snappy', 'lz4'] [2021-04-30 19:33:41,283] DEBUG: No available compression types supported on both ends. locally supported: odict_keys([]). remotely supported: ['snappy', 'lz4'] DEBUG:cassandra.connection:Sending StartupMessage on <LibevConnection(140047615677608) 10.0.3.128:9042> [2021-04-30 19:33:41,283] DEBUG: Sending StartupMessage on <LibevConnection(140047615677608) 10.0.3.128:9042> DEBUG:cassandra.connection:Sent StartupMessage on <LibevConnection(140047615677608) 10.0.3.128:9042> [2021-04-30 19:33:41,283] DEBUG: Sent StartupMessage on <LibevConnection(140047615677608) 10.0.3.128:9042> DEBUG:root:Resolved 10.0.1.64 to 10-0-1-64.prod-k8ssandra-dc1-all-pods-service.default.svc.cluster.local [2021-04-30 19:33:41,283] DEBUG: Resolved 10.0.1.64 to 10-0-1-64.prod-k8ssandra-dc1-all-pods-service.default.svc.cluster.local DEBUG:root:Resolved 10.0.2.189 to prod-k8ssandra-dc1-us-east-1b-sts-0.prod-k8ssandra-dc1-service.default.svc.cluster.local [2021-04-30 19:33:41,284] DEBUG: Resolved 10.0.2.189 to prod-k8ssandra-dc1-us-east-1b-sts-0.prod-k8ssandra-dc1-service.default.svc.cluster.local DEBUG:root:Resolved 10.0.3.128 to 10-0-3-128.prod-k8ssandra-dc1-all-pods-service.default.svc.cluster.local [2021-04-30 19:33:41,284] DEBUG: Resolved 10.0.3.128 to 10-0-3-128.prod-k8ssandra-dc1-all-pods-service.default.svc.cluster.local DEBUG:cassandra.connection:Got AuthenticateMessage on new connection (140047615677608) from 10.0.3.128:9042: org.apache.cassandra.auth.PasswordAuthenticator [2021-04-30 19:33:41,284] DEBUG: Got AuthenticateMessage on new connection (140047615677608) from 10.0.3.128:9042: org.apache.cassandra.auth.PasswordAuthenticator DEBUG:cassandra.connection:Sending SASL-based auth response on <LibevConnection(140047615677608) 10.0.3.128:9042> [2021-04-30 19:33:41,284] DEBUG: Sending SASL-based auth response on <LibevConnection(140047615677608) 10.0.3.128:9042> DEBUG:cassandra.connection:Connection <LibevConnection(140047615677608) 10.0.3.128:9042> successfully authenticated [2021-04-30 19:33:41,365] DEBUG: Connection <LibevConnection(140047615677608) 10.0.3.128:9042> successfully authenticated DEBUG:cassandra.pool:Finished initializing connection for host 10.0.3.128:9042 [2021-04-30 19:33:41,365] DEBUG: Finished initializing connection for host 10.0.3.128:9042 DEBUG:cassandra.cluster:Added pool for host 10.0.3.128:9042 to session [2021-04-30 19:33:41,365] DEBUG: Added pool for host 10.0.3.128:9042 to session DEBUG:cassandra.io.libevreactor:Closing connection (140047616714960) to 10.0.2.189:9042 [2021-04-30 19:33:41,365] DEBUG: Closing connection (140047616714960) to 10.0.2.189:9042 DEBUG:cassandra.io.libevreactor:Closed socket to 10.0.2.189:9042 [2021-04-30 19:33:41,366] DEBUG: Closed socket to 10.0.2.189:9042 DEBUG:cassandra.io.libevreactor:Closing connection (140047615680584) to 10.0.1.64:9042 [2021-04-30 19:33:41,366] DEBUG: Closing connection (140047615680584) to 10.0.1.64:9042 DEBUG:cassandra.io.libevreactor:Closed socket to 10.0.1.64:9042 [2021-04-30 19:33:41,366] DEBUG: Closed socket to 10.0.1.64:9042 DEBUG:cassandra.io.libevreactor:Closing connection (140047615677608) to 10.0.3.128:9042 [2021-04-30 19:33:41,366] DEBUG: Closing connection (140047615677608) to 10.0.3.128:9042 DEBUG:cassandra.io.libevreactor:Closed socket to 10.0.3.128:9042 [2021-04-30 19:33:41,366] DEBUG: Closed socket to 10.0.3.128:9042 DEBUG:cassandra.cluster:Shutting down Cluster Scheduler [2021-04-30 19:33:41,366] DEBUG: Shutting down Cluster Scheduler DEBUG:cassandra.cluster:Shutting down control connection [2021-04-30 19:33:41,366] DEBUG: Shutting down control connection DEBUG:cassandra.io.libevreactor:Closing connection (140047616713896) to 10.0.2.189:9042 [2021-04-30 19:33:41,366] DEBUG: Closing connection (140047616713896) to 10.0.2.189:9042 DEBUG:cassandra.io.libevreactor:All Connections currently closed, event loop ended [2021-04-30 19:33:41,366] DEBUG: All Connections currently closed, event loop ended DEBUG:cassandra.io.libevreactor:Closed socket to 10.0.2.189:9042 [2021-04-30 19:33:41,366] DEBUG: Closed socket to 10.0.2.189:9042 DEBUG:urllib3.connectionpool:https://s3.amazonaws.com:443 "POST /prod-k8ssandra2-s3-bucket/prod-k8ssandra-dc1-us-east-1b-sts-0.prod-k8ssandra-dc1-service.default.svc.cluster.local/test/meta/schema.cql?uploads= HTTP/1.1" 403 None [2021-04-30 19:33:41,429] DEBUG: https://s3.amazonaws.com:443 "POST /prod-k8ssandra2-s3-bucket/prod-k8ssandra-dc1-us-east-1b-sts-0.prod-k8ssandra-dc1-service.default.svc.cluster.local/test/meta/schema.cql?uploads= HTTP/1.1" 403 None DEBUG:urllib3.connectionpool:Resetting dropped connection: s3.amazonaws.com [2021-04-30 19:34:01,437] DEBUG: Resetting dropped connection: s3.amazonaws.com DEBUG:urllib3.connectionpool:https://s3.amazonaws.com:443 "POST /prod-k8ssandra2-s3-bucket/prod-k8ssandra-dc1-us-east-1b-sts-0.prod-k8ssandra-dc1-service.default.svc.cluster.local/test/meta/schema.cql?uploads= HTTP/1.1" 403 None [2021-04-30 19:34:01,494] DEBUG: https://s3.amazonaws.com:443 "POST /prod-k8ssandra2-s3-bucket/prod-k8ssandra-dc1-us-east-1b-sts-0.prod-k8ssandra-dc1-service.default.svc.cluster.local/test/meta/schema.cql?uploads= HTTP/1.1" 403 None DEBUG:urllib3.connectionpool:Resetting dropped connection: s3.amazonaws.com [2021-04-30 19:34:07,296] DEBUG: Resetting dropped connection: s3.amazonaws.com DEBUG:urllib3.connectionpool:https://s3.amazonaws.com:443 "POST /prod-k8ssandra2-s3-bucket/prod-k8ssandra-dc1-us-east-1b-sts-0.prod-k8ssandra-dc1-service.default.svc.cluster.local/test/meta/schema.cql?uploads= HTTP/1.1" 403 None [2021-04-30 19:34:07,350] DEBUG: https://s3.amazonaws.com:443 "POST /prod-k8ssandra2-s3-bucket/prod-k8ssandra-dc1-us-east-1b-sts-0.prod-k8ssandra-dc1-service.default.svc.cluster.local/test/meta/schema.cql?uploads= HTTP/1.1" 403 None ERROR:root:backup failed Traceback (most recent call last): File "/home/cassandra/medusa/service/grpc/server.py", line 51, in Backup medusa.backup_node.main(self.config, request.name, None, False, "differential") File "/home/cassandra/medusa/backup_node.py", line 227, in main config File "/home/cassandra/medusa/utils.py", line 35, in handle_exception raise exception File "/home/cassandra/medusa/backup_node.py", line 190, in main node_backup.schema = schema File "/home/cassandra/medusa/storage/node_backup.py", line 137, in schema self._storage.storage_driver.upload_blob_from_string(self.schema_path, schema) File "/home/cassandra/.local/lib/python3.6/site-packages/retrying.py", line 49, in wrapped_f return Retrying(_dargs, _dkw).call(f, _args, _kw) File "/home/cassandra/.local/lib/python3.6/site-packages/retrying.py", line 212, in call raise attempt.get() File "/home/cassandra/.local/lib/python3.6/site-packages/retrying.py", line 247, in get six.reraise(self.value[0], self.value[1], self.value[2]) File "/home/cassandra/.local/lib/python3.6/site-packages/six.py", line 703, in reraise raise value File "/home/cassandra/.local/lib/python3.6/site-packages/retrying.py", line 200, in call attempt = Attempt(fn(_args, *_kwargs), attempt_number, False) File "/home/cassandra/medusa/storage/abstract_storage.py", line 65, in upload_blob_from_string object_name=str(path) File "/home/cassandra/.local/lib/python3.6/site-packages/libcloud/storage/drivers/s3.py", line 753, in upload_object_via_stream storage_class=ex_storage_class) File "/home/cassandra/.local/lib/python3.6/site-packages/libcloud/storage/drivers/s3.py", line 989, in _put_object_multipart headers=headers) File "/home/cassandra/.local/lib/python3.6/site-packages/libcloud/storage/drivers/s3.py", line 573, in _initiate_multipart headers=headers, params=params) File "/home/cassandra/.local/lib/python3.6/site-packages/libcloud/common/base.py", line 655, in request response = responseCls(kwargs) File "/home/cassandra/.local/lib/python3.6/site-packages/libcloud/common/base.py", line 166, in init message=self.parse_error(), File "/home/cassandra/.local/lib/python3.6/site-packages/libcloud/storage/drivers/s3.py", line 138, in parse_error raise InvalidCredsError(self.body) libcloud.common.types.InvalidCredsError: '<?xml version="1.0" encoding="UTF-8"?>\nAccessDeniedAccess DeniedC8QKKGB0B3090Z1Ds3R0e+Rgl+U6j4/sPtdpSjP7nHgb46O50ltwWDzsFmOj8qJjxzOB9Nb/nKLsIThm4K2gbK+8OfI=' [2021-04-30 19:34:07,350] ERROR: backup failed Traceback (most recent call last): File "/home/cassandra/medusa/service/grpc/server.py", line 51, in Backup medusa.backup_node.main(self.config, request.name, None, False, "differential") File "/home/cassandra/medusa/backup_node.py", line 227, in main config File "/home/cassandra/medusa/utils.py", line 35, in handle_exception raise exception File "/home/cassandra/medusa/backup_node.py", line 190, in main node_backup.schema = schema File "/home/cassandra/medusa/storage/node_backup.py", line 137, in schema self._storage.storage_driver.upload_blob_from_string(self.schema_path, schema) File "/home/cassandra/.local/lib/python3.6/site-packages/retrying.py", line 49, in wrapped_f return Retrying(_dargs, _dkw).call(f, _args, _kw) File "/home/cassandra/.local/lib/python3.6/site-packages/retrying.py", line 212, in call raise attempt.get() File "/home/cassandra/.local/lib/python3.6/site-packages/retrying.py", line 247, in get six.reraise(self.value[0], self.value[1], self.value[2]) File "/home/cassandra/.local/lib/python3.6/site-packages/six.py", line 703, in reraise raise value File "/home/cassandra/.local/lib/python3.6/site-packages/retrying.py", line 200, in call attempt = Attempt(fn(_args, *_kwargs), attempt_number, False) File "/home/cassandra/medusa/storage/abstract_storage.py", line 65, in upload_blob_from_string object_name=str(path) File "/home/cassandra/.local/lib/python3.6/site-packages/libcloud/storage/drivers/s3.py", line 753, in upload_object_via_stream storage_class=ex_storage_class) File "/home/cassandra/.local/lib/python3.6/site-packages/libcloud/storage/drivers/s3.py", line 989, in _put_object_multipart headers=headers) File "/home/cassandra/.local/lib/python3.6/site-packages/libcloud/storage/drivers/s3.py", line 573, in _initiate_multipart headers=headers, params=params) File "/home/cassandra/.local/lib/python3.6/site-packages/libcloud/common/base.py", line 655, in request response = responseCls(kwargs) File "/home/cassandra/.local/lib/python3.6/site-packages/libcloud/common/base.py", line 166, in init* message=self.parse_error(), File "/home/cassandra/.local/lib/python3.6/site-packages/libcloud/storage/drivers/s3.py", line 138, in parse_error raise InvalidCredsError(self.body) libcloud.common.types.InvalidCredsError: '<?xml version="1.0" encoding="UTF-8"?>\nAccessDeniedAccess DeniedC8QKKGB0B3090Z1Ds3R0e+Rgl+U6j4/sPtdpSjP7nHgb46O50ltwWDzsFmOj8qJjxzOB9Nb/nKLsIThm4K2gbK+8OfI=' DEBUG:urllib3.connectionpool:Resetting dropped connection: s3.amazonaws.com [2021-04-30 19:34:41,515] DEBUG: Resetting dropped connection: s3.amazonaws.com DEBUG:urllib3.connectionpool:https://s3.amazonaws.com:443 "POST /prod-k8ssandra2-s3-bucket/prod-k8ssandra-dc1-us-east-1b-sts-0.prod-k8ssandra-dc1-service.default.svc.cluster.local/test/meta/schema.cql?uploads= HTTP/1.1" 403 None [2021-04-30 19:34:41,570] DEBUG: https://s3.amazonaws.com:443 "POST /prod-k8ssandra2-s3-bucket/prod-k8ssandra-dc1-us-east-1b-sts-0.prod-k8ssandra-dc1-service.default.svc.cluster.local/test/meta/schema.cql?uploads= HTTP/1.1" 403 None DEBUG:urllib3.connectionpool:Resetting dropped connection: s3.amazonaws.com [2021-04-30 19:36:01,633] DEBUG: Resetting dropped connection: s3.amazonaws.com DEBUG:urllib3.connectionpool:https://s3.amazonaws.com:443 "POST /prod-k8ssandra2-s3-bucket/prod-k8ssandra-dc1-us-east-1b-sts-0.prod-k8ssandra-dc1-service.default.svc.cluster.local/test/meta/schema.cql?uploads= HTTP/1.1" 403 None [2021-04-30 19:36:01,699] DEBUG: https://s3.amazonaws.com:443 "POST /prod-k8ssandra2-s3-bucket/prod-k8ssandra-dc1-us-east-1b-sts-0.prod-k8ssandra-dc1-service.default.svc.cluster.local/test/meta/schema.cql?uploads= HTTP/1.1" 403 None DEBUG:urllib3.connectionpool:Resetting dropped connection: s3.amazonaws.com [2021-04-30 19:38:01,800] DEBUG: Resetting dropped connection: s3.amazonaws.com DEBUG:urllib3.connectionpool:https://s3.amazonaws.com:443 "POST /prod-k8ssandra2-s3-bucket/prod-k8ssandra-dc1-us-east-1b-sts-0.prod-k8ssandra-dc1-service.default.svc.cluster.local/test/meta/schema.cql?uploads= HTTP/1.1" 403 None [2021-04-30 19:38:01,854] DEBUG: https://s3.amazonaws.com:443 "POST /prod-k8ssandra2-s3-bucket/prod-k8ssandra-dc1-us-east-1b-sts-0.prod-k8ssandra-dc1-service.default.svc.cluster.local/test/meta/schema.cql?uploads= HTTP/1.1" 403 None DEBUG:urllib3.connectionpool:Resetting dropped connection: s3.amazonaws.com [2021-04-30 19:40:01,953] DEBUG: Resetting dropped connection: s3.amazonaws.com DEBUG:urllib3.connectionpool:https://s3.amazonaws.com:443 "POST /prod-k8ssandra2-s3-bucket/prod-k8ssandra-dc1-us-east-1b-sts-0.prod-k8ssandra-dc1-service.default.svc.cluster.local/test/meta/schema.cql?uploads= HTTP/1.1" 403 None [2021-04-30 19:40:02,009] DEBUG: https://s3.amazonaws.com:443 "POST /prod-k8ssandra2-s3-bucket/prod-k8ssandra-dc1-us-east-1b-sts-0.prod-k8ssandra-dc1-service.default.svc.cluster.local/test/meta/schema.cql?uploads= HTTP/1.1" 403 None DEBUG:urllib3.connectionpool:Resetting dropped connection: s3.amazonaws.com [2021-04-30 19:42:02,057] DEBUG: Resetting dropped connection: s3.amazonaws.com DEBUG:urllib3.connectionpool:https://s3.amazonaws.com:443 "POST /prod-k8ssandra2-s3-bucket/prod-k8ssandra-dc1-us-east-1b-sts-0.prod-k8ssandra-dc1-service.default.svc.cluster.local/test/meta/schema.cql?uploads= HTTP/1.1" 403 None [2021-04-30 19:42:02,118] DEBUG: https://s3.amazonaws.com:443 "POST /prod-k8ssandra2-s3-bucket/prod-k8ssandra-dc1-us-east-1b-sts-0.prod-k8ssandra-dc1-service.default.svc.cluster.local/test/meta/schema.cql?uploads= HTTP/1.1" 403 None ERROR:root:backup failed Traceback (most recent call last): File "/home/cassandra/medusa/service/grpc/server.py", line 51, in Backup medusa.backup_node.main(self.config, request.name, None, False, "differential") File "/home/cassandra/medusa/backup_node.py", line 227, in main config File "/home/cassandra/medusa/utils.py", line 35, in handle_exception raise exception File "/home/cassandra/medusa/backup_node.py", line 190, in main node_backup.schema = schema File "/home/cassandra/medusa/storage/node_backup.py", line 137, in schema self._storage.storage_driver.upload_blob_from_string(self.schema_path, schema) File "/home/cassandra/.local/lib/python3.6/site-packages/retrying.py", line 49, in wrapped_f return Retrying(_dargs, _dkw).call(f, _args, _kw) File "/home/cassandra/.local/lib/python3.6/site-packages/retrying.py", line 212, in call raise attempt.get() File "/home/cassandra/.local/lib/python3.6/site-packages/retrying.py", line 247, in get six.reraise(self.value[0], self.value[1], self.value[2]) File "/home/cassandra/.local/lib/python3.6/site-packages/six.py", line 703, in reraise raise value File "/home/cassandra/.local/lib/python3.6/site-packages/retrying.py", line 200, in call attempt = Attempt(fn(_args, _kwargs), attempt_number, False) File "/home/cassandra/medusa/storage/abstract_storage.py", line 65, in upload_blob_from_string object_name=str(path) File "/home/cassandra/.local/lib/python3.6/site-packages/libcloud/storage/drivers/s3.py", line 753, in upload_object_via_stream storage_class=ex_storage_class) File "/home/cassandra/.local/lib/python3.6/site-packages/libcloud/storage/drivers/s3.py", line 989, in _put_object_multipart headers=headers) File "/home/cassandra/.local/lib/python3.6/site-packages/libcloud/storage/drivers/s3.py", line 573, in _initiate_multipart headers=headers, params=params) File "/home/cassandra/.local/lib/python3.6/site-packages/libcloud/common/base.py", line 655, in request response = responseCls(kwargs) File "/home/cassandra/.local/lib/python3.6/site-packages/libcloud/common/base.py", line 166, in init message=self.parse_error(), File "/home/cassandra/.local/lib/python3.6/site-packages/libcloud/storage/drivers/s3.py", line 138, in parse_error raise InvalidCredsError(self.body) libcloud.common.types.InvalidCredsError: '<?xml version="1.0" encoding="UTF-8"?>\nAccessDeniedAccess DeniedB6FPBNY9TPPHEMSE7De4yhrVyAB0ZCJGNYyfTUVHdAr0ARKobV/UyAvjv6Qx/dmkXg/fdQit2AM7j/hdTspC5S3L9Kw=' [2021-04-30 19:42:02,118] ERROR: backup failed Traceback (most recent call last): File "/home/cassandra/medusa/service/grpc/server.py", line 51, in Backup medusa.backup_node.main(self.config, request.name, None, False, "differential") File "/home/cassandra/medusa/backup_node.py", line 227, in main config File "/home/cassandra/medusa/utils.py", line 35, in handle_exception raise exception File "/home/cassandra/medusa/backup_node.py", line 190, in main node_backup.schema = schema File "/home/cassandra/medusa/storage/node_backup.py", line 137, in schema self._storage.storage_driver.upload_blob_from_string(self.schema_path, schema) File "/home/cassandra/.local/lib/python3.6/site-packages/retrying.py", line 49, in wrapped_f return Retrying(_dargs, _dkw).call(f, _args, _kw) File "/home/cassandra/.local/lib/python3.6/site-packages/retrying.py", line 212, in call raise attempt.get() File "/home/cassandra/.local/lib/python3.6/site-packages/retrying.py", line 247, in get six.reraise(self.value[0], self.value[1], self.value[2]) File "/home/cassandra/.local/lib/python3.6/site-packages/six.py", line 703, in reraise raise value File "/home/cassandra/.local/lib/python3.6/site-packages/retrying.py", line 200, in call attempt = Attempt(fn(_args, *_kwargs), attempt_number, False) File "/home/cassandra/medusa/storage/abstract_storage.py", line 65, in upload_blob_from_string object_name=str(path) File "/home/cassandra/.local/lib/python3.6/site-packages/libcloud/storage/drivers/s3.py", line 753, in upload_object_via_stream storage_class=ex_storage_class) File "/home/cassandra/.local/lib/python3.6/site-packages/libcloud/storage/drivers/s3.py", line 989, in _put_object_multipart headers=headers) File "/home/cassandra/.local/lib/python3.6/site-packages/libcloud/storage/drivers/s3.py", line 573, in _initiate_multipart headers=headers, params=params) File "/home/cassandra/.local/lib/python3.6/site-packages/libcloud/common/base.py", line 655, in request response = responseCls(kwargs) File "/home/cassandra/.local/lib/python3.6/site-packages/libcloud/common/base.py", line 166, in init** message=self.parse_error(), File "/home/cassandra/.local/lib/python3.6/site-packages/libcloud/storage/drivers/s3.py", line 138, in parse_error raise InvalidCredsError(self.body) libcloud.common.types.InvalidCredsError: '<?xml version="1.0" encoding="UTF-8"?>\nAccessDeniedAccess DeniedB6FPBNY9TPPHEMSE7De4yhrVyAB0ZCJGNYyfTUVHdAr0ARKobV/UyAvjv6Qx/dmkXg/fdQit2AM7j/hdTspC5S3L9Kw='



┆Issue is synchronized with this [Jiraserver Task](https://k8ssandra.atlassian.net/browse/K8SSAND-172) by [Unito](https://www.unito.io)
┆Issue Number: K8SSAND-172
┆Priority: Medium
bradfordcp commented 3 years ago

Note the IAM policy being used for both tests is the one generated by Terraform. In my case this looked like:

{
    "Statement": [
        {
            "Action": [
                "s3:*"
            ],
            "Effect": "Allow",
            "Resource": "arn:aws:s3:::prod-k8ssandra2-s3-bucket"
        }
    ],
    "Version": "2012-10-17"
}
jsanda commented 3 years ago

This sounds like an IAM issue, not a Medusa issue. Am I missing something?

bradfordcp commented 3 years ago

Potentially, looking at the Medusa docs I see:

            "Resource": [
                "arn:aws:s3:::<bucket-name>",
                "arn:aws:s3:::<bucket-name>/*"
            ]

which differs from the one we have generated by Terraform. I'll spin the environment back up and test.

bradfordcp commented 3 years ago

This ended up being the fix. Changing the policy to

{
    "Statement": [
        {
            "Action": [
                "s3:*"
            ],
            "Effect": "Allow",
            "Resource": [
                "arn:aws:s3:::dev-bradford-s3-bucket",
                "arn:aws:s3:::dev-bradford-s3-bucket/*"
            ]
        }
    ],
    "Version": "2012-10-17"
}

Resolved my issue and I was able to use the IAM roles assigned to the k8s workers. Moving this ticket to k8ssandra/k8ssandra-terraform to get the issue resolved upstream. Thanks!