Our cudtomer is using QNAP object storage as the target for a backup copy job with immutability enabled.
I don't know if this is a QNAP issue, but the backup copy job is completed every 10 days when blocks are generated, and takes more than 24 hours.
object-storage-as-backup-target-f52/qna ... 85139.html
As a result, even the backup job fails with the following error.
Code: Select all
Item [<vib file name>] is locked by running session Immutable Backup Job - <Backup copy job name> [Backup Copy]
several tens of minutes, and it seems that the extension of the immutability period is taking time.
Code: Select all
[20.06.2025 02:06:57.051] <46> Info (3) [ArchiveImmutabilityManager] Immutability settings: Generation interval in days 10, Immutability interval in days 60
[20.06.2025 02:06:57.051] <46> Info (3) [ArchiveImmutabilityManager] Creating or updating generation info. New generation info: Expiration date UTC 2025/06/29 17:06:57, Immutable until UTC 2025/08/28 17:06:57
[20.06.2025 02:06:57.067] <46> Info (3) [DirectBackupExtension] BackupId: 50cce671-9d22-440b-b760-46614307f065, ExtentId: 69fe5555-8cf5-442a-9d2f-356a7d7a0f70, GenerationExpirationDateUtc 2025-06-29T17:06:57.0518545Z, GenerationImmutableTillUtc 2025-08-28T17:06:57.0518545Z
[20.06.2025 02:06:57.067] <46> Info (3) Setting immutability for backup Immutable Backup Job - QNAP-BK2\KANRI-FILE - KANRI-FILE:50cce671-9d22-440b-b760-46614307f065
[20.06.2025 02:06:57.067] <46> Info (3) Using generation immutability interval, backup will be immutable until 2025/08/28 17:06:57
[20.06.2025 02:06:57.067] <46> Info (3) [AP] (aead5e41) command: 'Invoke: Cloud.SetCurrentImmutabilityGeneration { (EString) ConnectionId = 69fe5555-8cf5-442a-9d2f-356a7d7a0f70; (EString) BackupId = 0bc67861-133f-431f-9ae2-6f96f87d8601; (EDateTime) ImmutableTillUtc = 2025-08-28 17:06:57; }'
[20.06.2025 02:06:57.864] <56> Info (4) [AP] (aead5e41) output: <VCPCommandResult result="true" exception="" />
[20.06.2025 02:06:57.864] <56> Info (4) [AP] (aead5e41) output: <VCPCommandArgs />
[20.06.2025 02:06:57.879] <53> Info (4) [AP] (aead5e41) output: >
[20.06.2025 02:06:57.879] <46> Info (3) Checking if reconnect is needed
[20.06.2025 02:06:57.879] <46> Info (3) [CSimpleCopyStorageAlg] Creating incremental storage.
[20.06.2025 02:06:57.942] <46> Info (3) [Mutex] Created mutex [Global\DirectBackupStorageInfo[d2490fa4-7531-4d99-a5fb-012f38ee69a9]]
[20.06.2025 02:06:57.942] <46> Info (3) [Mutex] Acquired mutex [Global\DirectBackupStorageInfo[d2490fa4-7531-4d99-a5fb-012f38ee69a9]]
[20.06.2025 02:06:57.957] <46> Info (3) [Mutex] Releasing mutex [Global\DirectBackupStorageInfo[d2490fa4-7531-4d99-a5fb-012f38ee69a9]]
[20.06.2025 02:06:57.957] <46> Info (3) [AP] (aead5e41) command: 'prepStorageForWriteEx\ncloud://<Path ConnId="69fe5555-8cf5-442a-9d2f-356a7d7a0f70" BackupId="0bc67861-133f-431f-9ae2-6f96f87d8601" StgId="{dc981646-f54e-40e0-a08d-b2b1f43bc7f2}" LocalPath="" Tag="KANRI-FILE.vm-28D2025-06-19T225402_C6D8.vib"/>\n1024\n3\n'
[20.06.2025 02:06:59.113] <73> Info (4) [AP] (aead5e41) output: >
[20.06.2025 02:06:59.129] <46> Info (3) [CBlobStorageCommander] Creating checkpoint. Vbm will be loaded from blob storage
[20.06.2025 02:06:59.129] <46> Info (3) [AP] (aead5e41) command: 'Invoke: Cloud.FindLastCheckpointId { (EString) ConnectionId = 69fe5555-8cf5-442a-9d2f-356a7d7a0f70; (EString) BackupId = 0bc67861-133f-431f-9ae2-6f96f87d8601; (EString) ClientId = 9797a14b-5e9e-4c52-8053-306be4393e78; }'
[20.06.2025 02:07:00.035] <56> Info (4) [AP] (aead5e41) output: <VCPCommandResult result="true" exception="" />
[20.06.2025 02:07:00.035] <56> Info (4) [AP] (aead5e41) output: <VCPCommandArgs><Item key="LastCheckpointId" type="EUInt64" value="1008" /></VCPCommandArgs>
[20.06.2025 02:07:00.035] <56> Info (4) [AP] (aead5e41) output: >
[20.06.2025 02:07:00.035] <46> Info (3) [AP] (aead5e41) command: 'Invoke: Cloud.GetCheckpointInfo { (EString) ConnectionId = 69fe5555-8cf5-442a-9d2f-356a7d7a0f70; (EString) BackupId = 0bc67861-133f-431f-9ae2-6f96f87d8601; (EUInt64) CheckpointId = 1008; (EString) ClientId = 9797a14b-5e9e-4c52-8053-306be4393e78; }'
[20.06.2025 02:07:01.551] <46> Info (3) [CloudBackupServiceLocker] Locking cloudBackupId 0bc67861-133f-431f-9ae2-6f96f87d8601 for write
[20.06.2025 02:07:01.551] <46> Info (3) [CloudBackupLock] Locking 1 cloudbackup(s) as write-only: 0bc67861-133f-431f-9ae2-6f96f87d8601
[20.06.2025 02:07:01.551] <46> Info (3) [LockResolver] Getting conflicting sessions
[20.06.2025 02:07:01.551] <46> Info (3) [LockResolver] No conflicting sessions found
[20.06.2025 02:07:01.551] <46> Info (3) [API] Creating new lease. TTL: [00:05:00]
[20.06.2025 02:07:01.551] <46> Info (3) [API] New lease was created. Id: [3727ac94-c119-4ee0-a7ca-e0258f721705], TTL: [00:05:00]
[20.06.2025 02:07:01.551] <46> Info (3) [LeaseKeeper] Created. LeaseId: 3727ac94-c119-4ee0-a7ca-e0258f721705, TTL: [300 sec], ignoreExceptions: [False].
[20.06.2025 02:07:01.613] <46> Info (3) [CloudBackupLock] CloudBackup(s) have been locked, lockIds: [79750ab3-fdd9-42dd-92ba-c389178101a4]
[20.06.2025 02:07:01.613] <46> Info (3) Created CCloudBackupEmptyLocker
[20.06.2025 02:07:01.613] <46> Info (3) [AP] (aead5e41) command: 'Invoke: Cloud.FindLastCheckpointId { (EString) ConnectionId = 69fe5555-8cf5-442a-9d2f-356a7d7a0f70; (EString) BackupId = 0bc67861-133f-431f-9ae2-6f96f87d8601; (EString) ClientId = 9797a14b-5e9e-4c52-8053-306be4393e78; }'
[20.06.2025 02:07:03.847] <54> Info (4) [AP] (aead5e41) output: <VCPCommandResult result="true" exception="" />
[20.06.2025 02:07:03.847] <56> Info (4) [AP] (aead5e41) output: <VCPCommandArgs><Item key="LastCheckpointId" type="EUInt64" value="1008" /></VCPCommandArgs>
[20.06.2025 02:07:03.847] <56> Info (4) [AP] (aead5e41) output: >
[20.06.2025 02:07:03.863] <46> Info (3) [CBlobStorageCommander] Creating checkpoint for cloud backup [50cce671-9d22-440b-b760-46614307f065]. Vbm version: [643]
[20.06.2025 02:07:03.910] <46> Info (3) [AP] (aead5e41) command: 'Invoke: Cloud.CreateCheckpoint { (EString) ConnectionId = 69fe5555-8cf5-442a-9d2f-356a7d7a0f70; (EString) BackupId = 0bc67861-133f-431f-9ae2-6f96f87d8601; (EBlob) VbmContent = {EBlob: 597923 bytes}; (EUInt64) LastCheckpointId = 1008; }'
[20.06.2025 02:07:03.972] <53> Info (4) [AP] (aead5e41) output: --size: 1000
[20.06.2025 02:07:07.596] <54> Info (4) [AP] (aead5e41) output: 0
[20.06.2025 02:07:07.893] <73> Info (4) [AP] (aead5e41) output: 20
[20.06.2025 02:10:33.386] <44> Info (4) [AP] (aead5e41) output: 21
[20.06.2025 02:37:03.955] <46> Info (3) [AP] Waiting for completion. Id: [0x3765649], Time: 00:30:00.0450836
[20.06.2025 03:07:03.996] <46> Info (3) [AP] Waiting for completion. Id: [0x3765649], Time: 01:00:00.0869259
[20.06.2025 03:37:04.048] <46> Info (3) [AP] Waiting for completion. Id: [0x3765649], Time: 01:30:00.1385502
[20.06.2025 04:07:04.088] <46> Info (3) [AP] Waiting for completion. Id: [0x3765649], Time: 02:00:00.1780165
[20.06.2025 04:37:04.137] <46> Info (3) [AP] Waiting for completion. Id: [0x3765649], Time: 02:30:00.2273083
[20.06.2025 05:07:04.180] <46> Info (3) [AP] Waiting for completion. Id: [0x3765649], Time: 03:00:00.2701488
[20.06.2025 05:37:04.230] <46> Info (3) [AP] Waiting for completion. Id: [0x3765649], Time: 03:30:00.3207880
[20.06.2025 06:07:04.281] <46> Info (3) [AP] Waiting for completion. Id: [0x3765649], Time: 04:00:00.3712499
[20.06.2025 06:37:04.319] <46> Info (3) [AP] Waiting for completion. Id: [0x3765649], Time: 04:30:00.4091527
[20.06.2025 07:07:04.357] <46> Info (3) [AP] Waiting for completion. Id: [0x3765649], Time: 05:00:00.4471219
[20.06.2025 07:37:04.394] <46> Info (3) [AP] Waiting for completion. Id: [0x3765649], Time: 05:30:00.4848791
[20.06.2025 08:07:04.435] <46> Info (3) [AP] Waiting for completion. Id: [0x3765649], Time: 06:00:00.5254256
[20.06.2025 08:37:04.481] <46> Info (3) [AP] Waiting for completion. Id: [0x3765649], Time: 06:30:00.5712973
[20.06.2025 09:07:04.526] <46> Info (3) [AP] Waiting for completion. Id: [0x3765649], Time: 07:00:00.6165749
[20.06.2025 09:37:04.564] <46> Info (3) [AP] Waiting for completion. Id: [0x3765649], Time: 07:30:00.6545905
[20.06.2025 10:07:04.603] <46> Info (3) [AP] Waiting for completion. Id: [0x3765649], Time: 08:00:00.6938104
[20.06.2025 10:37:04.640] <46> Info (3) [AP] Waiting for completion. Id: [0x3765649], Time: 08:30:00.7305917
[20.06.2025 11:07:04.678] <46> Info (3) [AP] Waiting for completion. Id: [0x3765649], Time: 09:00:00.7687400
[20.06.2025 11:37:04.727] <46> Info (3) [AP] Waiting for completion. Id: [0x3765649], Time: 09:30:00.8177610
[20.06.2025 12:07:04.774] <46> Info (3) [AP] Waiting for completion. Id: [0x3765649], Time: 10:00:00.8646062
[20.06.2025 12:37:04.826] <46> Info (3) [AP] Waiting for completion. Id: [0x3765649], Time: 10:30:00.9162749
[20.06.2025 13:07:04.868] <46> Info (3) [AP] Waiting for completion. Id: [0x3765649], Time: 11:00:00.9589297
[20.06.2025 13:37:04.913] <46> Info (3) [AP] Waiting for completion. Id: [0x3765649], Time: 11:30:01.0031952
[20.06.2025 14:07:04.955] <46> Info (3) [AP] Waiting for completion. Id: [0x3765649], Time: 12:00:01.0457460
[20.06.2025 14:37:05.001] <46> Info (3) [AP] Waiting for completion. Id: [0x3765649], Time: 12:30:01.0911714
[20.06.2025 15:07:05.041] <46> Info (3) [AP] Waiting for completion. Id: [0x3765649], Time: 13:00:01.1318824
[20.06.2025 15:37:05.085] <46> Info (3) [AP] Waiting for completion. Id: [0x3765649], Time: 13:30:01.1751199
[20.06.2025 16:07:05.126] <46> Info (3) [AP] Waiting for completion. Id: [0x3765649], Time: 14:00:01.2169350
[20.06.2025 16:37:05.164] <46> Info (3) [AP] Waiting for completion. Id: [0x3765649], Time: 14:30:01.2548134
[20.06.2025 17:07:05.209] <46> Info (3) [AP] Waiting for completion. Id: [0x3765649], Time: 15:00:01.2999680
[20.06.2025 17:37:05.259] <46> Info (3) [AP] Waiting for completion. Id: [0x3765649], Time: 15:30:01.3498110
[20.06.2025 18:07:05.308] <46> Info (3) [AP] Waiting for completion. Id: [0x3765649], Time: 16:00:01.3981700
[20.06.2025 18:37:05.353] <46> Info (3) [AP] Waiting for completion. Id: [0x3765649], Time: 16:30:01.4430546
[20.06.2025 18:43:25.239] <49> Info (4) [AP] (aead5e41) output: 22
[20.06.2025 18:44:00.329] <53> Info (4) [AP] (aead5e41) output: 23
[20.06.2025 18:47:59.495] <34> Info (4) [AP] (aead5e41) output: 24
[20.06.2025 18:50:39.753] <62> Info (4) [AP] (aead5e41) output: 25
[20.06.2025 18:53:06.541] <39> Info (4) [AP] (aead5e41) output: 26
[20.06.2025 18:56:22.073] <52> Info (4) [AP] (aead5e41) output: 27
[20.06.2025 19:07:05.394] <46> Info (3) [AP] Waiting for completion. Id: [0x3765649], Time: 17:00:01.4847595
[20.06.2025 19:26:22.326] <39> Info (4) [AP] (aead5e41) output: 28
[20.06.2025 19:30:23.346] <67> Info (4) [AP] (aead5e41) output: 29
[20.06.2025 19:33:32.859] <13> Info (4) [AP] (aead5e41) output: 30
[20.06.2025 19:34:24.507] <51> Info (4) [AP] (aead5e41) output: 31
[20.06.2025 19:37:05.447] <46> Info (3) [AP] Waiting for completion. Id: [0x3765649], Time: 17:30:01.5369915
[20.06.2025 19:38:58.004] <13> Info (4) [AP] (aead5e41) output: 32
[20.06.2025 19:43:09.384] <53> Info (4) [AP] (aead5e41) output: 33
[20.06.2025 19:45:22.853] <42> Info (4) [AP] (aead5e41) output: 34
[20.06.2025 19:49:30.482] <52> Info (4) [AP] (aead5e41) output: 35
[20.06.2025 20:07:05.496] <46> Info (3) [AP] Waiting for completion. Id: [0x3765649], Time: 18:00:01.5862887
[20.06.2025 20:37:05.548] <46> Info (3) [AP] Waiting for completion. Id: [0x3765649], Time: 18:30:01.6382728
[20.06.2025 21:07:05.585] <46> Info (3) [AP] Waiting for completion. Id: [0x3765649], Time: 19:00:01.6757571
[20.06.2025 21:24:32.666] <13> Info (4) [AP] (aead5e41) output: 36
[20.06.2025 21:29:45.219] <68> Info (4) [AP] (aead5e41) output: 37
[20.06.2025 21:32:55.790] <51> Info (4) [AP] (aead5e41) output: 38
[20.06.2025 21:36:19.661] <13> Info (4) [AP] (aead5e41) output: 39
[20.06.2025 21:37:05.634] <46> Info (3) [AP] Waiting for completion. Id: [0x3765649], Time: 19:30:01.7240692
[20.06.2025 21:40:49.343] <44> Info (4) [AP] (aead5e41) output: 40
[20.06.2025 21:44:32.063] <35> Info (4) [AP] (aead5e41) output: 41
[20.06.2025 21:49:59.086] <63> Info (4) [AP] (aead5e41) output: 42
[20.06.2025 22:04:03.761] <71> Info (4) [AP] (aead5e41) output: 43
[20.06.2025 22:06:40.581] <71> Info (4) [AP] (aead5e41) output: 44
[20.06.2025 22:07:05.671] <46> Info (3) [AP] Waiting for completion. Id: [0x3765649], Time: 20:00:01.7616610
[20.06.2025 22:10:57.269] <42> Info (4) [AP] (aead5e41) output: 45
[20.06.2025 22:14:42.970] <69> Info (4) [AP] (aead5e41) output: 46
[20.06.2025 22:17:33.631] <04> Info (4) [AP] (aead5e41) output: 47
[20.06.2025 22:29:35.442] <64> Info (4) [AP] (aead5e41) output: 48
[20.06.2025 22:34:28.160] <62> Info (4) [AP] (aead5e41) output: 49
[20.06.2025 22:37:05.721] <46> Info (3) [AP] Waiting for completion. Id: [0x3765649], Time: 20:30:01.8113452
[20.06.2025 22:37:11.204] <62> Info (4) [AP] (aead5e41) output: 50
[20.06.2025 22:42:13.328] <58> Info (4) [AP] (aead5e41) output: 51
[20.06.2025 22:49:57.637] <15> Info (4) [AP] (aead5e41) output: 52
[20.06.2025 22:53:42.945] <71> Info (4) [AP] (aead5e41) output: 53
[20.06.2025 23:07:05.761] <46> Info (3) [AP] Waiting for completion. Id: [0x3765649], Time: 21:00:01.8513042
[20.06.2025 23:37:05.809] <46> Info (3) [AP] Waiting for completion. Id: [0x3765649], Time: 21:30:01.8997385
[20.06.2025 23:59:30.169] <42> Info (4) [AP] (aead5e41) output: 54
[21.06.2025 00:02:12.343] <13> Info (4) [AP] (aead5e41) output: 55
[21.06.2025 00:07:05.857] <46> Info (3) [AP] Waiting for completion. Id: [0x3765649], Time: 22:00:01.9478540
[21.06.2025 00:07:11.778] <34> Info (4) [AP] (aead5e41) output: 56
[21.06.2025 00:11:56.660] <56> Info (4) [AP] (aead5e41) output: 57
[21.06.2025 00:18:56.507] <61> Info (4) [AP] (aead5e41) output: 58
[21.06.2025 00:22:01.486] <55> Info (4) [AP] (aead5e41) output: 59
[21.06.2025 00:28:55.124] <71> Info (4) [AP] (aead5e41) output: 60
[21.06.2025 00:31:46.123] <13> Info (4) [AP] (aead5e41) output: 61
[21.06.2025 00:37:05.895] <46> Info (3) [AP] Waiting for completion. Id: [0x3765649], Time: 22:30:01.9855455
[21.06.2025 01:07:05.943] <46> Info (3) [AP] Waiting for completion. Id: [0x3765649], Time: 23:00:02.0335505
[21.06.2025 01:12:22.243] <48> Info (4) [AP] (aead5e41) output: 62
[21.06.2025 01:19:13.048] <67> Info (4) [AP] (aead5e41) output: 63
[21.06.2025 01:26:33.016] <61> Info (4) [AP] (aead5e41) output: 64
[21.06.2025 01:30:17.739] <48> Info (4) [AP] (aead5e41) output: 65
[21.06.2025 01:35:07.965] <39> Info (4) [AP] (aead5e41) output: 66
[21.06.2025 01:37:05.983] <46> Info (3) [AP] Waiting for completion. Id: [0x3765649], Time: 23:30:02.0735257
[21.06.2025 01:43:37.921] <64> Info (4) [AP] (aead5e41) output: 67
[21.06.2025 01:49:50.119] <50> Info (4) [AP] (aead5e41) output: 68
[21.06.2025 01:53:37.566] <67> Info (4) [AP] (aead5e41) output: 73
[21.06.2025 01:53:38.581] <69> Info (4) [AP] (aead5e41) output: 75
[21.06.2025 01:53:53.875] <30> Info (4) [AP] (aead5e41) output: 76
[21.06.2025 01:54:16.606] <04> Info (4) [AP] (aead5e41) output: 77
[21.06.2025 01:54:19.902] <04> Info (4) [AP] (aead5e41) output: 80
[21.06.2025 01:54:21.027] <69> Info (4) [AP] (aead5e41) output: 83
[21.06.2025 01:54:48.788] <04> Info (4) [AP] (aead5e41) output: 84
[21.06.2025 01:57:23.744] <66> Info (4) [AP] (aead5e41) output: 85
[21.06.2025 01:57:24.744] <70> Info (4) [AP] (aead5e41) output: 86
[21.06.2025 02:00:05.997] <37> Info (4) [AP] (aead5e41) output: <VCPCommandResult result="true" exception="" />
[21.06.2025 02:00:05.997] <37> Info (4) [AP] (aead5e41) output: <VCPCommandArgs><Item key="CheckpointId" type="EUInt64" value="1009" /><Item key="Owner.Description" type="EString" value="DL380-BK" /><Item key="Owner.Exists" type="EBoolean" value="true" /><Item key="Owner.Id" type="EString" value="{9797a14b-5e9e-4c52-8053-306be4393e78}" /><Item key="Owner.Type" type="EString" value="VBR" /><Item key="Owner.UserData" type="EString" value="<RepositoryState Signature=~=T3eZ0QajcTfpTuB44cgK4npy0y2NOh+p4m/gQCfmlWB8z88X/DMohJH68WbV6SDj8klzc9qCfRbL59pXQFzBFHtmQE+a4aXzYCDQBa3oyEz+txEz/7MsEp3T45Z7qE1J7ZNy3uGlxAvN0PwjvhXDQb6+Agda4aFl24Tj2uH8r5amZvLSOUQ4jck7tklpLrnOJcIzt7G5bCXjAm5Y6Y+mHIKisK8CbKsTdSj8LJDirLd7b3R+ELrMwR8BdXX8k6WxCm+mRDVkX7Dp34C9PXNDHGuC4egzg8IANzXluJMx7sH37wQUHxt4uUTL5GrSB+BoNuASzNOdxsAv7y6/886b3A==~=><RepositoryState Status=~=2~= IsFull=~=False~= RepositoryVersion=~=1~= GenerationInterval=~=10.00:00:00~=><DirectBackupImmutabilitySettings HasImmutableCapacityOrArchiveTierExtent=~=False~= IsGovernanceMode=~=False~=><ImmutabilitySettings IsEnabled=~=True~= IntervalDays=~=60~= /></DirectBackupImmutabilitySettings><StorageEncryptionInfo Enabled=~=False~= /><JobList /></RepositoryState></RepositoryState>" /></VCPCommandArgs>
[21.06.2025 02:00:05.997] <39> Info (4) [AP] (aead5e41) output: >
[21.06.2025 02:00:05.997] <46> Info (3) [DirectBackupExtension] SetLatestCheckpoint ExtentId: 69fe5555-8cf5-442a-9d2f-356a7d7a0f70, BackupId: 50cce671-9d22-440b-b760-46614307f065, LatestCheckpoint: 1009, UsedSize: 4415468857326,GenerationExpirationDateUtc: 2025/06/29 17:06:57, GenerationImmutableTillUtc: 2025/08/28 17:06:57
[21.06.2025 02:00:05.997] <46> Info (3) Created CCloudBackupEmptyLocker
Is this true?
After analyzing the chain structure of the source backup and unlocking the source backup, is it possible to extend the immutability period without locking the source backup?
Also, if I could adjust the days of the week for this immutability extension process, I think I could avoid the error by not running the backup job on those days.
Is it possible to specify the day of the week as well as the interval?
https://www.veeam.com/kb4470
In addition, the backup job fails after checking the vib lock five times every 10 minutes.
Is there a way to change the number of retries or the interval?
Thank you in advance for your insights.