Medusa v0.22.0 apparently skipping backup for some nodes in the cluster

[ftarrega]

Project board link

Hi there.

So I'm writing to understand what to me looks like an odd and invalid behaviour when running medusa. I have a 4 nodes Cassandra cluster, for which the fourth node has been recently added (few weeks back), so it's the youngest, and when I try to run a backup on all nodes in the cluster, the only node medusa takes a backup from is the fourth one.

I've pasted below 2 log snippets, one from node 2 and one from node 4. We can see medusa does a lot more on 4 than what it does on 2 and on node 4 it ends up with a backup roughly the size of the node's share of the data as per nodetool status output (about 48.2GB). There are no ERROR messages or exceptions on the log for node 2 run, or any of the other 3 nodes runs.

Something else I noticed comparing these 2 runs is that medusa cleans up after itself at the end of the run for node 4, but not for the others, AS IF some error had happened.

Please find copy of medusa.ini at the very end of this ticket

Please beware more sensitive info has been masked as per my company's policy

Should you require further details, please let me know.

Thanks in advance

(py3-11) cassandra@ip-192-168-0-3:~ . nodetool -u cassandra -pw *************** listsnapshots | grep medusa
medusa-system_environment_20240729 my_keyspace_x table_1 971.21 KiB 972.18 KiB
medusa-system_environment_20240729 my_keyspace_y table_1 557.81 KiB 558.65 KiB
medusa-system_environment_20240729 my_keyspace_y table_2 1.08 MiB 1.08 MiB
medusa-system_environment_20240729 my_keyspace_y table_3 16.58 KiB 17.42 KiB
medusa-system_environment_20240729 my_keyspace_y table_4 0 bytes 1.54 KiB
medusa-system_environment_20240729 my_keyspace_y table_5 0 bytes 858 bytes
medusa-system_environment_20240729 my_keyspace_y table_6 3.95 GiB 3.95 GiB
medusa-system_environment_20240729 my_keyspace_y table_7 1.08 MiB 1.08 MiB
(...)

(py3-11) cassandra@ip-192-168-0-2:~ . nodetool -u user1 -pw ********************* status
Datacenter: DC1

Status=Up/Down
|/ State=Normal/Leaving/Joining/Moving
-- Address Load Tokens Owns (effective) Host ID Rack
UN 192.168.0.1 57.22 GiB 256 78.6% -9a2e-4f45-b51f-**** rack1
UN 192.168.0.2 59.78 GiB 256 76.9% -b214-40c6-9d65-**** rack1
UN 192.168.0.3 51.53 GiB 256 71.7% -5f56-42e5-acc3-**** rack1
UN 192.168.0.4 48.2 GiB 256 72.7% -5ffd-4e22-af9b-**** rack1

Partial printout of medusa log on the 4th node:

(py3-11) cassandra@ip-192-168-0-4:~ . medusa -v --config-file /opt/apps/cassandra-medusa/etc/medusa/medusa.ini backup --backup-name=system_environment_20240729
[2024-07-29 17:22:17,375] DEBUG: Loading configuration from /opt/apps/cassandra-medusa/etc/medusa/medusa.ini
[2024-07-29 17:22:17,377] INFO: Resolving ip address
[2024-07-29 17:22:17,378] INFO: ip address to resolve 192.168.0.4
[2024-07-29 17:22:17,378] DEBUG: Resolved 192.168.0.4 to ip-192-168-0-4.eu-central-1.compute.internal
[2024-07-29 17:22:17,378] DEBUG: Logging to file options: LoggingConfig(enabled='1', file='/opt/apps/cassandra-medusa/logs/medusa.log', format='[%(asctime)s] %(levelname)s: %(message)s', level='INFO', maxBytes='20000000', backupCount='200')
[2024-07-29 17:22:17,379] INFO: Registered backup id system_environment_20240729
[2024-07-29 17:22:17,380] INFO: Monitoring provider is noop
[2024-07-29 17:22:17,380] DEBUG: Loading storage_provider: s3_eu_central
[2024-07-29 17:22:17,385] INFO: Using credentials CensoredCredentials(access_key_id=None, secret_access_key=*****, region=eu-central-1)
[2024-07-29 17:22:17,386] INFO: Connecting to s3_eu_central with args {}
[2024-07-29 17:22:17,483] DEBUG: Starting backup preparations with Mode: differential
[2024-07-29 17:22:17,493] DEBUG: This server has systemd: True
[2024-07-29 17:22:17,556] DEBUG: Blob system_environment/ip-192-168-0-4.eu-central-1.compute.internal/system_environment_20240729/meta/schema.cql was not found in cache.
[2024-07-29 17:22:17,556] DEBUG: [Storage] Getting object system_environment/ip-192-168-0-4.eu-central-1.compute.internal/system_environment_20240729/meta/schema.cql
[2024-07-29 17:22:17,557] DEBUG: Using selector: GeventSelector
[2024-07-29 17:22:17,642] DEBUG: [S3 Storage] Object system_environment/ip-192-168-0-4.eu-central-1.compute.internal/system_environment_20240729/meta/schema.cql not found
[2024-07-29 17:22:17,642] INFO: Starting backup using Stagger: None Mode: differential Name: system_environment_20240729
[2024-07-29 17:22:17,642] DEBUG: Updated from existing status: -1 to new status: 0 for backup id: system_environment_20240729
[2024-07-29 17:22:17,643] DEBUG: Process psutil.Process(pid=257106, name='medusa', status='running', started='17:22:15') was set to use only idle IO and CPU resources
[2024-07-29 17:22:17,643] INFO: Saving tokenmap and schema
[2024-07-29 17:22:17,858] DEBUG: Checking placement using dc and rack...
[2024-07-29 17:22:17,858] INFO: Resolving ip address 192.168.0.4
[2024-07-29 17:22:17,858] INFO: ip address to resolve 192.168.0.4
[2024-07-29 17:22:17,859] DEBUG: Resolved 192.168.0.4 to ip-192-168-0-4.eu-central-1.compute.internal
[2024-07-29 17:22:17,859] DEBUG: Checking host 192.168.0.4 against 192.168.0.4/ip-192-168-0-4.eu-central-1.compute.internal
[2024-07-29 17:22:17,859] INFO: Resolving ip address 192.168.0.2
[2024-07-29 17:22:17,859] INFO: ip address to resolve 192.168.0.2
[2024-07-29 17:22:17,862] DEBUG: Resolved 192.168.0.2 to ip-192-168-0-2.eu-central-1.compute.internal
[2024-07-29 17:22:17,862] INFO: Resolving ip address 192.168.0.4
[2024-07-29 17:22:17,862] INFO: ip address to resolve 192.168.0.4
[2024-07-29 17:22:17,862] DEBUG: Resolved 192.168.0.4 to ip-192-168-0-4.eu-central-1.compute.internal
[2024-07-29 17:22:17,862] INFO: Resolving ip address 192.168.0.1
[2024-07-29 17:22:17,862] INFO: ip address to resolve 192.168.0.1
[2024-07-29 17:22:17,865] DEBUG: Resolved 192.168.0.1 to ip-192-168-0-1.eu-central-1.compute.internal
[2024-07-29 17:22:17,931] DEBUG: [S3 Storage] Uploading object from stream -> s3://medusa-s3-bucket/system_environment/ip-192-168-0-4.eu-central-1.compute.internal/system_environment_20240729/meta/schema.cql
[2024-07-29 17:22:18,054] DEBUG: [S3 Storage] Uploading object from stream -> s3://medusa-s3-bucket/system_environment/ip-192-168-0-4.eu-central-1.compute.internal/system_environment_20240729/meta/tokenmap.json
[2024-07-29 17:22:18,091] INFO: Saving server version
[2024-07-29 17:22:18,351] DEBUG: [S3 Storage] Uploading object from stream -> s3://medusa-s3-bucket/system_environment/ip-192-168-0-4.eu-central-1.compute.internal/system_environment_20240729/meta/server_version.json
[2024-07-29 17:22:18,383] DEBUG: [S3 Storage] Uploading object from stream -> s3://medusa-s3-bucket/system_environment/ip-192-168-0-4.eu-central-1.compute.internal/system_environment_20240729/meta/differential
[2024-07-29 17:22:18,415] DEBUG: Blob system_environment/ip-192-168-0-4.eu-central-1.compute.internal/system_environment_20240729/meta/tokenmap.json was not found in cache.
[2024-07-29 17:22:18,415] DEBUG: [Storage] Getting object system_environment/ip-192-168-0-4.eu-central-1.compute.internal/system_environment_20240729/meta/tokenmap.json
[2024-07-29 17:22:18,423] DEBUG: [Storage] Reading blob system_environment/ip-192-168-0-4.eu-central-1.compute.internal/system_environment_20240729/meta/tokenmap.json...
[2024-07-29 17:22:18,439] DEBUG: [S3 Storage] Uploading object from stream -> s3://medusa-s3-bucket/system_environment/index/backup_index/system_environment_20240729/tokenmap_ip-192-168-0-4.eu-central-1.compute.internal.json
[2024-07-29 17:22:18,490] DEBUG: [Storage] Getting object system_environment/ip-192-168-0-4.eu-central-1.compute.internal/system_environment_20240729/meta/schema.cql
[2024-07-29 17:22:18,504] DEBUG: [Storage] Reading blob system_environment/ip-192-168-0-4.eu-central-1.compute.internal/system_environment_20240729/meta/schema.cql...
[2024-07-29 17:22:18,527] DEBUG: [S3 Storage] Uploading object from stream -> s3://medusa-s3-bucket/system_environment/index/backup_index/system_environment_20240729/schema_ip-192-168-0-4.eu-central-1.compute.internal.cql
[2024-07-29 17:22:18,653] DEBUG: Blob system_environment/ip-192-168-0-4.eu-central-1.compute.internal/system_environment_20240729/meta/schema.cql was not found in cache.
[2024-07-29 17:22:18,653] DEBUG: [Storage] Getting object system_environment/ip-192-168-0-4.eu-central-1.compute.internal/system_environment_20240729/meta/schema.cql
[2024-07-29 17:22:18,662] DEBUG: Blob system_environment/ip-192-168-0-4.eu-central-1.compute.internal/system_environment_20240729/meta/schema.cql last modification time is 2024-07-29 17:22:18+00:00
[2024-07-29 17:22:18,662] DEBUG: [S3 Storage] Uploading object from stream -> s3://medusa-s3-bucket/system_environment/index/backup_index/system_environment_20240729/started_ip-192-168-0-4.eu-central-1.compute.internal_1722273738.timestamp
[2024-07-29 17:22:18,698] DEBUG: [S3 Storage] Uploading object from stream -> s3://medusa-s3-bucket/system_environment/index/backup_index/system_environment_20240729/differential_ip-192-168-0-4.eu-central-1.compute.internal
[2024-07-29 17:22:18,728] INFO: Creating snapshot
[2024-07-29 17:22:18,737] DEBUG: Executing: nodetool -Dcom.sun.jndi.rmiURLParsing=legacy -u cassandra -pw ************* -h 192.168.0.4 -p 7199 snapshot -t medusa-system_environment_20240729
[2024-07-29 17:22:20,567] INFO: Listing already backed up files for node ip-192-168-0-4.eu-central-1.compute.internal
[2024-07-29 17:22:21,639] INFO: Backing up my_keyspace_1.my_keyspace_1_table_1-76304830636011ee99cb43377f5bb057
[2024-07-29 17:22:21,640] DEBUG: Snapshot destination path: system_environment/ip-192-168-0-4.eu-central-1.compute.internal/data/my_keyspace_1/my_keyspace_1_table_1-76304830636011ee99cb43377f5bb057
[2024-07-29 17:22:21,641] DEBUG: [S3 Storage] Uploading /opt/apps/cassandra/storage/data/my_keyspace_1/my_keyspace_1_table_1-76304830636011ee99cb43377f5bb057/snapshots/medusa-system_environment_20240729/md-69-big-Statistics.db (5.175KiB) -> system_environment/ip-192-168-0-4.eu-central-1.compute.internal/data/my_keyspace_1/my_keyspace_1_table_1-76304830636011ee99cb43377f5bb057/md-69-big-Statistics.db
[2024-07-29 17:22:21,641] DEBUG: [S3 Storage] Uploading /opt/apps/cassandra/storage/data/my_keyspace_1/my_keyspace_1_table_1-76304830636011ee99cb43377f5bb057/snapshots/medusa-system_environment_20240729/md-69-big-Index.db (212.000B) -> system_environment/ip-192-168-0-4.eu-central-1.compute.internal/data/my_keyspace_1/my_keyspace_1_table_1-76304830636011ee99cb43377f5bb057/md-69-big-Index.db
[2024-07-29 17:22:21,642] DEBUG: [S3 Storage] Uploading /opt/apps/cassandra/storage/data/my_keyspace_1/my_keyspace_1_table_1-76304830636011ee99cb43377f5bb057/snapshots/medusa-system_environment_20240729/md-69-big-Filter.db (16.000B) -> system_environment/ip-192-168-0-4.eu-central-1.compute.internal/data/my_keyspace_1/my_keyspace_1_table_1-76304830636011ee99cb43377f5bb057/md-69-big-Filter.db
[2024-07-29 17:22:21,642] DEBUG: [S3 Storage] Uploading /opt/apps/cassandra/storage/data/my_keyspace_1/my_keyspace_1_table_1-76304830636011ee99cb43377f5bb057/snapshots/medusa-system_environment_20240729/md-69-big-Summary.db (80.000B) -> system_environment/ip-192-168-0-4.eu-central-1.compute.internal/data/my_keyspace_1/my_keyspace_1_table_1-76304830636011ee99cb43377f5bb057/md-69-big-Summary.db
[2024-07-29 17:22:21,643] DEBUG: [S3 Storage] Uploading /opt/apps/cassandra/storage/data/my_keyspace_1/my_keyspace_1_table_1-76304830636011ee99cb43377f5bb057/snapshots/medusa-system_environment_20240729/md-69-big-Data.db (24.477KiB) -> system_environment/ip-192-168-0-4.eu-central-1.compute.internal/data/my_keyspace_1/my_keyspace_1_table_1-76304830636011ee99cb43377f5bb057/md-69-big-Data.db
[2024-07-29 17:22:21,643] DEBUG: [S3 Storage] Uploading /opt/apps/cassandra/storage/data/my_keyspace_1/my_keyspace_1_table_1-76304830636011ee99cb43377f5bb057/snapshots/medusa-system_environment_20240729/md-69-big-TOC.txt (92.000B) -> system_environment/ip-192-168-0-4.eu-central-1.compute.internal/data/my_keyspace_1/my_keyspace_1_table_1-76304830636011ee99cb43377f5bb057/md-69-big-TOC.txt
[2024-07-29 17:22:21,643] DEBUG: [S3 Storage] Uploading /opt/apps/cassandra/storage/data/my_keyspace_1/my_keyspace_1_table_1-76304830636011ee99cb43377f5bb057/snapshots/medusa-system_environment_20240729/md-69-big-CompressionInfo.db (59.000B) -> system_environment/ip-192-168-0-4.eu-central-1.compute.internal/data/my_keyspace_1/my_keyspace_1_table_1-76304830636011ee99cb43377f5bb057/md-69-big-CompressionInfo.db
[2024-07-29 17:22:21,644] DEBUG: [S3 Storage] Uploading /opt/apps/cassandra/storage/data/my_keyspace_1/my_keyspace_1_table_1-76304830636011ee99cb43377f5bb057/snapshots/medusa-system_environment_20240729/md-69-big-Digest.crc32 (10.000B) -> system_environment/ip-192-168-0-4.eu-central-1.compute.internal/data/my_keyspace_1/my_keyspace_1_table_1-76304830636011ee99cb43377f5bb057/md-69-big-Digest.crc32
[2024-07-29 17:22:21,916] INFO: Skipping upload of 64 files in my_keyspace_1.my_keyspace_1_table_1-76304830636011ee99cb43377f5bb057 because they are already in storage
[2024-07-29 17:22:21,917] INFO: Backing up my_keyspace_1.my_keyspace_1_table_2-78f13cf0636011ee99cb43377f5bb057
[2024-07-29 17:22:21,917] DEBUG: Snapshot destination path: system_environment/ip-192-168-0-4.eu-central-1.compute.internal/data/my_keyspace_1/my_keyspace_1_table_2-78f13cf0636011ee99cb43377f5bb057
[2024-07-29 17:22:21,917] INFO: Backing up my_keyspace_1.my_keyspace_1_table_3-25515170636f11ee99cb43377f5bb057
[2024-07-29 17:22:21,917] DEBUG: Snapshot destination path: system_environment/ip-192-168-0-4.eu-central-1.compute.internal/data/my_keyspace_1/my_keyspace_1_table_3-25515170636f11ee99cb43377f5bb057
[2024-07-29 17:22:21,917] INFO: Backing up my_keyspace_1.my_keyspace_1_table_4-7a57f8e0636011ee99cb43377f5bb057
[2024-07-29 17:22:21,917] DEBUG: Snapshot destination path: system_environment/ip-192-168-0-4.eu-central-1.compute.internal/data/my_keyspace_1/my_keyspace_1_table_4-7a57f8e0636011ee99cb43377f5bb057
[2024-07-29 17:22:21,917] INFO: Backing up my_keyspace_1.my_keyspace_1_table_5-6ab82f90636011ee99cb43377f5bb057
[2024-07-29 17:22:21,918] DEBUG: Snapshot destination path: system_environment/ip-192-168-0-4.eu-central-1.compute.internal/data/my_keyspace_1/my_keyspace_1_table_5-6ab82f90636011ee99cb43377f5bb057
[2024-07-29 17:22:21,918] INFO: Skipping upload of 8 files in my_keyspace_1.my_keyspace_1_table_5-6ab82f90636011ee99cb43377f5bb057 because they are already in storage
[2024-07-29 17:22:21,918] INFO: Backing up my_keyspace_1.my_keyspace_1_table_6-78632dc0636011ee99cb43377f5bb057
[2024-07-29 17:22:21,918] DEBUG: Snapshot destination path: system_environment/ip-192-168-0-4.eu-central-1.compute.internal/data/my_keyspace_1/my_keyspace_1_table_6-78632dc0636011ee99cb43377f5bb057
[2024-07-29 17:22:21,918] INFO: Backing up my_keyspace_1.geoaddress_cust_rel-7b048c90636011ee99cb43377f5bb057
(...)
[2024-07-29 17:25:55,246] INFO: Backing up system_distributed.view_build_status-5582b59f8e4e35e1b9133acada51eb04
[2024-07-29 17:25:55,247] DEBUG: Snapshot destination path: system_environment/ip-192-168-0-4.eu-central-1.compute.internal/data/system_distributed/view_build_status-5582b59f8e4e35e1b9133acada51eb04
[2024-07-29 17:25:55,249] DEBUG: Cleaning up Cassandra snapshot
[2024-07-29 17:25:55,250] DEBUG: Executing: nodetool -Dcom.sun.jndi.rmiURLParsing=legacy -u cassandra -pw cassandra -h 192.168.0.4 -p 7199 clearsnapshot -t medusa-system_environment_20240729
[2024-07-29 17:25:56,957] DEBUG: nodetool output: Requested clearing snapshot(s) for [all keyspaces] with snapshot name [medusa-system_environment_20240729]
[2024-07-29 17:25:56,957] DEBUG: Blob system_environment/ip-192-168-0-4.eu-central-1.compute.internal/system_environment_20240729/meta/server_version.json was not found in cache.
[2024-07-29 17:25:56,957] DEBUG: [Storage] Getting object system_environment/ip-192-168-0-4.eu-central-1.compute.internal/system_environment_20240729/meta/server_version.json
[2024-07-29 17:25:56,969] DEBUG: [Storage] Reading blob system_environment/ip-192-168-0-4.eu-central-1.compute.internal/system_environment_20240729/meta/server_version.json...
[2024-07-29 17:25:56,984] INFO: Updating backup index
[2024-07-29 17:25:56,997] DEBUG: [S3 Storage] Uploading object from stream -> s3://medusa-s3-bucket/system_environment/ip-192-168-0-4.eu-central-1.compute.internal/system_environment_20240729/meta/manifest.json
[2024-07-29 17:25:57,154] DEBUG: [Storage] Getting object system_environment/ip-192-168-0-4.eu-central-1.compute.internal/system_environment_20240729/meta/manifest.json
[2024-07-29 17:25:57,165] DEBUG: [Storage] Reading blob system_environment/ip-192-168-0-4.eu-central-1.compute.internal/system_environment_20240729/meta/manifest.json...
[2024-07-29 17:25:57,194] DEBUG: [S3 Storage] Uploading object from stream -> s3://medusa-s3-bucket/system_environment/index/backup_index/system_environment_20240729/manifest_ip-192-168-0-4.eu-central-1.compute.internal.json
[2024-07-29 17:25:57,304] DEBUG: Blob system_environment/ip-192-168-0-4.eu-central-1.compute.internal/system_environment_20240729/meta/manifest.json was not found in cache.
[2024-07-29 17:25:57,304] DEBUG: [Storage] Getting object system_environment/ip-192-168-0-4.eu-central-1.compute.internal/system_environment_20240729/meta/manifest.json
[2024-07-29 17:25:57,314] DEBUG: Blob system_environment/ip-192-168-0-4.eu-central-1.compute.internal/system_environment_20240729/meta/manifest.json last modification time is 2024-07-29 17:25:58+00:00
[2024-07-29 17:25:57,314] DEBUG: [S3 Storage] Uploading object from stream -> s3://medusa-s3-bucket/system_environment/index/backup_index/system_environment_20240729/finished_ip-192-168-0-4.eu-central-1.compute.internal_1722273958.timestamp
[2024-07-29 17:25:57,344] DEBUG: [Storage] Reading blob system_environment/ip-192-168-0-4.eu-central-1.compute.internal/system_environment_20240729/meta/tokenmap.json...
[2024-07-29 17:25:57,361] DEBUG: [S3 Storage] Uploading object from stream -> s3://medusa-s3-bucket/system_environment/index/latest_backup/ip-192-168-0-4.eu-central-1.compute.internal/tokenmap.json
[2024-07-29 17:25:57,406] DEBUG: [S3 Storage] Uploading object from stream -> s3://medusa-s3-bucket/system_environment/index/latest_backup/ip-192-168-0-4.eu-central-1.compute.internal/backup_name.txt
[2024-07-29 17:25:57,439] INFO: Backup done
[2024-07-29 17:25:57,439] INFO: - Started: 2024-07-29 17:22:17
- Started extracting data: 2024-07-29 17:22:18
- Finished: 2024-07-29 17:25:57
[2024-07-29 17:25:57,439] INFO: - Real duration: 0:03:38.710672 (excludes time waiting for other nodes)
[2024-07-29 17:25:57,445] INFO: - 5384 files, 48.21 GB
[2024-07-29 17:25:57,445] INFO: - 2480 files copied from host (2480 new, 0 reuploaded)
[2024-07-29 17:25:57,445] INFO: - 2904 kept from previous backup (system_environment_20240729)
[2024-07-29 17:25:57,445] DEBUG: Emitting metrics
[2024-07-29 17:25:57,450] DEBUG: Done emitting metrics
[2024-07-29 17:25:57,450] DEBUG: Updated from existing status: 0 to new status: 1 for backup id: system_environment_20240729
[2024-07-29 17:25:57,450] DEBUG: Done with backup, returning backup result information
[2024-07-29 17:25:57,451] DEBUG: Disconnecting from S3...

Partial printout of 2nd node:

(py3-11) cassandra@ip-192-168-0-2:~ . medusa -v --config-file /opt/apps/cassandra-medusa/etc/medusa/medusa.ini backup --backup-name=system_environment_20240729
[2024-07-29 17:24:08,170] DEBUG: Loading configuration from /opt/apps/cassandra-medusa/etc/medusa/medusa.ini
[2024-07-29 17:24:08,172] INFO: Resolving ip address
[2024-07-29 17:24:08,173] INFO: ip address to resolve 192.168.0.2
[2024-07-29 17:24:08,173] DEBUG: Resolved 192.168.0.2 to ip-192-168-0-2.eu-central-1.compute.internal
[2024-07-29 17:24:08,174] DEBUG: Logging to file options: LoggingConfig(enabled='1', file='/opt/apps/cassandra-medusa/logs/medusa.log', format='[%(asctime)s] %(levelname)s: %(message)s', level='INFO', maxBytes='20000000', backupCount='200')
[2024-07-29 17:24:08,174] INFO: Registered backup id system_environment_20240729
[2024-07-29 17:24:08,176] INFO: Monitoring provider is noop
[2024-07-29 17:24:08,176] DEBUG: Loading storage_provider: s3_eu_central
[2024-07-29 17:24:08,181] INFO: Using credentials CensoredCredentials(access_key_id=None, secret_access_key=*****, region=eu-central-1)
[2024-07-29 17:24:08,182] INFO: Connecting to s3_eu_central with args {}
[2024-07-29 17:24:08,281] DEBUG: Starting backup preparations with Mode: differential
[2024-07-29 17:24:08,291] DEBUG: This server has systemd: True
[2024-07-29 17:24:08,354] DEBUG: Blob cdh_xtest1/ip-192-168-0-2.eu-central-1.compute.internal/system_environment_20240729/meta/schema.cql was not found in cache.
[2024-07-29 17:24:08,354] DEBUG: [Storage] Getting object cdh_xtest1/ip-192-168-0-2.eu-central-1.compute.internal/system_environment_20240729/meta/schema.cql
[2024-07-29 17:24:08,354] DEBUG: Using selector: GeventSelector
[2024-07-29 17:24:08,441] DEBUG: [S3 Storage] Object cdh_xtest1/ip-192-168-0-2.eu-central-1.compute.internal/system_environment_20240729/meta/schema.cql not found
[2024-07-29 17:24:08,441] INFO: Starting backup using Stagger: None Mode: differential Name: system_environment_20240729
[2024-07-29 17:24:08,441] DEBUG: Updated from existing status: -1 to new status: 0 for backup id: system_environment_20240729
[2024-07-29 17:24:08,441] DEBUG: Process psutil.Process(pid=221876, name='medusa', status='running', started='17:24:06') was set to use only idle IO and CPU resources
[2024-07-29 17:24:08,442] INFO: Saving tokenmap and schema
[2024-07-29 17:24:08,715] DEBUG: Checking placement using dc and rack...
[2024-07-29 17:24:08,715] INFO: Resolving ip address 192.168.0.2
[2024-07-29 17:24:08,715] INFO: ip address to resolve 192.168.0.2
[2024-07-29 17:24:08,716] DEBUG: Resolved 192.168.0.2 to ip-192-168-0-2.eu-central-1.compute.internal
[2024-07-29 17:24:08,716] DEBUG: Checking host 192.168.0.2 against 192.168.0.2/ip-192-168-0-2.eu-central-1.compute.internal
[2024-07-29 17:24:08,716] INFO: Resolving ip address 192.168.0.2
[2024-07-29 17:24:08,717] INFO: ip address to resolve 192.168.0.2
[2024-07-29 17:24:08,717] DEBUG: Resolved 192.168.0.2 to ip-192-168-0-2.eu-central-1.compute.internal
[2024-07-29 17:24:08,717] INFO: Resolving ip address 192.168.0.4
[2024-07-29 17:24:08,717] INFO: ip address to resolve 192.168.0.4
[2024-07-29 17:24:08,720] DEBUG: Resolved 192.168.0.4 to ip-10-181-30-154.eu-central-1.compute.internal
[2024-07-29 17:24:08,720] INFO: Resolving ip address 192.168.0.1
[2024-07-29 17:24:08,720] INFO: ip address to resolve 192.168.0.1
[2024-07-29 17:24:08,722] DEBUG: Resolved 192.168.0.1 to ip-10-181-30-212.eu-central-1.compute.internal
[2024-07-29 17:24:08,724] DEBUG: [S3 Storage] Uploading object from stream -> s3://medusa-s3-bucket/cdh_xtest1/ip-192-168-0-2.eu-central-1.compute.internal/system_environment_20240729/meta/schema.cql
[2024-07-29 17:24:08,833] DEBUG: [S3 Storage] Uploading object from stream -> s3://medusa-s3-bucket/cdh_xtest1/ip-192-168-0-2.eu-central-1.compute.internal/system_environment_20240729/meta/tokenmap.json
[2024-07-29 17:24:08,880] INFO: Saving server version
[2024-07-29 17:24:09,139] DEBUG: [S3 Storage] Uploading object from stream -> s3://medusa-s3-bucket/cdh_xtest1/ip-192-168-0-2.eu-central-1.compute.internal/system_environment_20240729/meta/server_version.json
[2024-07-29 17:24:09,181] DEBUG: [S3 Storage] Uploading object from stream -> s3://medusa-s3-bucket/cdh_xtest1/ip-192-168-0-2.eu-central-1.compute.internal/system_environment_20240729/meta/differential
[2024-07-29 17:24:09,216] DEBUG: Blob cdh_xtest1/ip-192-168-0-2.eu-central-1.compute.internal/system_environment_20240729/meta/tokenmap.json was not found in cache.
[2024-07-29 17:24:09,216] DEBUG: [Storage] Getting object cdh_xtest1/ip-192-168-0-2.eu-central-1.compute.internal/system_environment_20240729/meta/tokenmap.json
[2024-07-29 17:24:09,227] DEBUG: [Storage] Reading blob cdh_xtest1/ip-192-168-0-2.eu-central-1.compute.internal/system_environment_20240729/meta/tokenmap.json...
[2024-07-29 17:24:09,245] DEBUG: [S3 Storage] Uploading object from stream -> s3://medusa-s3-bucket/cdh_xtest1/index/backup_index/system_environment_20240729/tokenmap_ip-192-168-0-2.eu-central-1.compute.internal.json
[2024-07-29 17:24:09,289] DEBUG: [Storage] Getting object cdh_xtest1/ip-192-168-0-2.eu-central-1.compute.internal/system_environment_20240729/meta/schema.cql
[2024-07-29 17:24:09,301] DEBUG: [Storage] Reading blob cdh_xtest1/ip-192-168-0-2.eu-central-1.compute.internal/system_environment_20240729/meta/schema.cql...
[2024-07-29 17:24:09,338] DEBUG: [S3 Storage] Uploading object from stream -> s3://medusa-s3-bucket/cdh_xtest1/index/backup_index/system_environment_20240729/schema_ip-192-168-0-2.eu-central-1.compute.internal.cql
[2024-07-29 17:24:09,464] DEBUG: Blob cdh_xtest1/ip-192-168-0-2.eu-central-1.compute.internal/system_environment_20240729/meta/schema.cql was not found in cache.
[2024-07-29 17:24:09,464] DEBUG: [Storage] Getting object cdh_xtest1/ip-192-168-0-2.eu-central-1.compute.internal/system_environment_20240729/meta/schema.cql
[2024-07-29 17:24:09,475] DEBUG: Blob cdh_xtest1/ip-192-168-0-2.eu-central-1.compute.internal/system_environment_20240729/meta/schema.cql last modification time is 2024-07-29 17:24:09+00:00
[2024-07-29 17:24:09,475] DEBUG: [S3 Storage] Uploading object from stream -> s3://medusa-s3-bucket/cdh_xtest1/index/backup_index/system_environment_20240729/started_ip-192-168-0-2.eu-central-1.compute.internal_1722273849.timestamp
[2024-07-29 17:24:09,514] DEBUG: [S3 Storage] Uploading object from stream -> s3://medusa-s3-bucket/cdh_xtest1/index/backup_index/system_environment_20240729/differential_ip-192-168-0-2.eu-central-1.compute.internal
[2024-07-29 17:24:09,552] INFO: Creating snapshot
[2024-07-29 17:24:09,552] DEBUG: Executing: nodetool -Dcom.sun.jndi.rmiURLParsing=legacy -u cassandra -pw *************** -h 192.168.0.2 -p 7199 snapshot -t medusa-system_environment_20240729
[2024-07-29 17:24:21,234] INFO: Listing already backed up files for node ip-192-168-0-2.eu-central-1.compute.internal
[2024-07-29 17:24:21,339] DEBUG: Cleaning up Cassandra snapshot
[2024-07-29 17:24:21,339] DEBUG: Blob cdh_xtest1/ip-192-168-0-2.eu-central-1.compute.internal/system_environment_20240729/meta/server_version.json was not found in cache.
[2024-07-29 17:24:21,339] DEBUG: [Storage] Getting object cdh_xtest1/ip-192-168-0-2.eu-central-1.compute.internal/system_environment_20240729/meta/server_version.json
[2024-07-29 17:24:21,352] DEBUG: [Storage] Reading blob cdh_xtest1/ip-192-168-0-2.eu-central-1.compute.internal/system_environment_20240729/meta/server_version.json...
[2024-07-29 17:24:21,367] INFO: Updating backup index
[2024-07-29 17:24:21,368] DEBUG: [S3 Storage] Uploading object from stream -> s3://medusa-s3-bucket/cdh_xtest1/ip-192-168-0-2.eu-central-1.compute.internal/system_environment_20240729/meta/manifest.json
[2024-07-29 17:24:21,409] DEBUG: [Storage] Getting object cdh_xtest1/ip-192-168-0-2.eu-central-1.compute.internal/system_environment_20240729/meta/manifest.json
[2024-07-29 17:24:21,421] DEBUG: [Storage] Reading blob cdh_xtest1/ip-192-168-0-2.eu-central-1.compute.internal/system_environment_20240729/meta/manifest.json...
[2024-07-29 17:24:21,437] DEBUG: [S3 Storage] Uploading object from stream -> s3://medusa-s3-bucket/cdh_xtest1/index/backup_index/system_environment_20240729/manifest_ip-192-168-0-2.eu-central-1.compute.internal.json
[2024-07-29 17:24:21,476] DEBUG: Blob cdh_xtest1/ip-192-168-0-2.eu-central-1.compute.internal/system_environment_20240729/meta/manifest.json was not found in cache.
[2024-07-29 17:24:21,476] DEBUG: [Storage] Getting object cdh_xtest1/ip-192-168-0-2.eu-central-1.compute.internal/system_environment_20240729/meta/manifest.json
[2024-07-29 17:24:21,487] DEBUG: Blob cdh_xtest1/ip-192-168-0-2.eu-central-1.compute.internal/system_environment_20240729/meta/manifest.json last modification time is 2024-07-29 17:24:22+00:00
[2024-07-29 17:24:21,487] DEBUG: [S3 Storage] Uploading object from stream -> s3://medusa-s3-bucket/cdh_xtest1/index/backup_index/system_environment_20240729/finished_ip-192-168-0-2.eu-central-1.compute.internal_1722273862.timestamp
[2024-07-29 17:24:21,526] DEBUG: [Storage] Reading blob cdh_xtest1/ip-192-168-0-2.eu-central-1.compute.internal/system_environment_20240729/meta/tokenmap.json...
[2024-07-29 17:24:21,544] DEBUG: [S3 Storage] Uploading object from stream -> s3://medusa-s3-bucket/cdh_xtest1/index/latest_backup/ip-192-168-0-2.eu-central-1.compute.internal/tokenmap.json
[2024-07-29 17:24:21,592] DEBUG: [S3 Storage] Uploading object from stream -> s3://medusa-s3-bucket/cdh_xtest1/index/latest_backup/ip-192-168-0-2.eu-central-1.compute.internal/backup_name.txt
[2024-07-29 17:24:21,630] INFO: Backup done
[2024-07-29 17:24:21,631] INFO: - Started: 2024-07-29 17:24:08
- Started extracting data: 2024-07-29 17:24:09
- Finished: 2024-07-29 17:24:21
[2024-07-29 17:24:21,631] INFO: - Real duration: 0:00:12.078773 (excludes time waiting for other nodes)
[2024-07-29 17:24:21,631] INFO: - 0 files, 0.00 B
[2024-07-29 17:24:21,631] INFO: - 0 files copied from host (0 new, 0 reuploaded)
[2024-07-29 17:24:21,631] INFO: - 0 kept from previous backup (system_environment_20240729)
[2024-07-29 17:24:21,631] DEBUG: Emitting metrics
[2024-07-29 17:24:21,631] DEBUG: Done emitting metrics
[2024-07-29 17:24:21,631] DEBUG: Updated from existing status: 0 to new status: 1 for backup id: system_environment_20240729
[2024-07-29 17:24:21,631] DEBUG: Done with backup, returning backup result information
[2024-07-29 17:24:21,631] DEBUG: Disconnecting from S3...

medusa.ini:

; Copyright 2019 Spotify AB. All rights reserved.

; Licensed under the Apache License, Version 2.0 (the "License");
; you may not use this file except in compliance with the License.
; You may obtain a copy of the License at
;
; http://www.apache.org/licenses/LICENSE-2.0
;
; Unless required by applicable law or agreed to in writing, software
; distributed under the License is distributed on an "AS IS" BASIS,
; WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
; See the License for the specific language governing permissions and
; limitations under the License.

[cassandra]
stop_cmd = /opt/apps/cassandra/cassandra/bin/stop-server
start_cmd = /opt/apps/cassandra/cassandra/bin/cassandra
config_file = /opt/apps/cassandra/cassandra/conf/cassandra.yaml
cql_username = user1
cql_password = *************************
; When using the following setting there must be files in:
; - <cql_k8s_secrets_path>/username containing username
; - <cql_k8s_secrets_path>/password containing password
;cql_k8s_secrets_path =
nodetool_username = cassandra
nodetool_password = ***************************
;nodetool_password_file_path =
;nodetool_k8s_secrets_path =
nodetool_host = 192.168.0.4
nodetool_port = 7199
;certfile=
;usercert=
;userkey=
;sstableloader_ts =
;sstableloader_tspw =
;sstableloader_ks =
;sstableloader_kspw =
;sstableloader_bin =

; Enable this to add the --ssl parameter to nodetool. The nodetool-ssl.properties is expected to be in the normal location
;nodetool_ssl = true

; Command ran to verify if Cassandra is running on a node. Defaults to "nodetool version"
;check_running = nodetool version

; Disable/Enable ip address resolving.
; Disabling this can help when fqdn resolving gives different domain names for local and remote nodes
; which makes backup succeed but Medusa sees them as incomplete.
; Defaults to True.
resolve_ip_addresses = True

; When true, almost all commands executed by Medusa are prefixed with sudo.
; Does not affect the use_sudo_for_restore setting in the storage section.
; See #318
; Defaults to True
;use_sudo = True

[storage]
storage_provider = s3_eu_central
; storage_provider should be either of "local", "google_storage", "azure_blobs" or the s3_* values from
; https://github.com/apache/libcloud/blob/trunk/libcloud/storage/types.py

; Name of the bucket used for storing backups
bucket_name = medusa-s3-bucket

; JSON key file for service account with access to GCS bucket or AWS credentials file (home-dir/.aws/credentials)
;key_file = /etc/medusa/credentials

; Path of the local storage bucket (used only with \local\ storage provider)
;base_path = /path/to/backups

; Any prefix used for multitenancy in the same bucket
prefix = system_environment

;fqdn =

; Number of days before backups are purged. 0 means backups don\t get purged by age (default)
max_backup_age = 3
; Number of backups to retain. Older backups will get purged beyond that number. 0 means backups don\t get purged by count (default)
max_backup_count = 0
; Both thresholds can be defined for backup purge.

; Used to throttle S3 backups/restores:
transfer_max_bandwidth = 1000MB/s

; Max number of concurrent downloads/uploads.
concurrent_transfers = 16

; Size over which uploads will be using multi part uploads. Defaults to 20MB.
multi_part_upload_threshold = 104857600

; GC grace period for backed up files. Prevents race conditions between purge and running backups
backup_grace_period_in_days = 2

; When not using sstableloader to restore data on a node, Medusa will copy snapshot files from a
; temporary location into the cassandra data directroy. Medusa will then attempt to change the
; ownership of the snapshot files so the cassandra user can access them.
; Depending on how users/file permissions are set up on the cassandra instance, the medusa user
; may need elevated permissions to manipulate the files in the cassandra data directory.
;
; This option does NOT replace the use_sudo option under the \cassandra\ section!
; See: #399
;
; Defaults to True
use_sudo_for_restore = False

;api_profile =

;host =
;port =

; Configures the use of SSL to connect to the object storage system.
;secure = True

; Enables verification of certificates used in case secure is set to True.
; Enabling this is not yet supported - we don\t have a good way to configure paths to custom certificates.
; ssl_verify = False

;aws_cli_path =

[monitoring]
;monitoring_provider = <Provider used for sending metrics. Currently either of "ffwd" or "local">

[ssh]
;username =
;key_file =
;port = <SSH port for use for restoring clusters. Default to port 22.
;cert_file =

[checks]
;health_check = <Which ports to check when verifying a node restored properly. Options are \cql\ (default), \thrift, \all.>
;query =
;expected_rows =
;expected_result = <Coma separated string representation of values returned by the query. Checks only 1st row returned, and only if specified>
;enable_md5_checks = <During backups and verify, use md5 calculations to determine file integrity (in addition to size, which is used by default)>

[logging]
; Controls file logging, disabled by default.
enabled = 1
file = /opt/apps/cassandra-medusa/logs/medusa.log
level = INFO

; Control the log output format
format = [%(asctime)s] %(levelname)s: %(message)s

; Size over which log file will rotate
maxBytes = 20000000

; How many log files to keep
backupCount = 200

[grpc]
; Set to true when running in grpc server mode.
; Allows to propagate the exceptions instead of exiting the program.
;enabled = False

[kubernetes]
; The following settings are only intended to be configured if Medusa is running in containers, preferably in Kubernetes.
;enabled = False
;cassandra_url = <URL of the management API snapshot endpoint. For example: http://127.0.0.1:8080/api/v0/ops/node/snapshots>

; Enables the use of the management API to create snapshots. Falls back to using Jolokia if not enabled.
;use_mgmt_api = True
;ca_cert = mutual_auth_ca.pem
;tls_cert = mutual_auth_client.crt
;tls_key = mutual_auth_client.key

[ftarrega]

Nevermind. It's a cassandra.yaml config issue.