alcionai / corso

Free, Secure, and Open-Source Backup for Microsoft 365
https://corsobackup.io
Apache License 2.0
182 stars 28 forks source link

[Bug]: 0.15.0: multiple previous state changes to collection / 0.19.0 RepoRef already in matcher #5309

Closed heimdal-31 closed 5 months ago

heimdal-31 commented 5 months ago

What happened?

We have been backing up a SharePoint site for months. Since November, we've been using the 0.15.0. We had a request to restore a top level folder that had disappeared and was outside the 30 day window for MS restore. We were told it existed 40+ days ago.

When we went to restore, the last successful backup for this site was on 1/5. Luckily, the folder is archival, so restoring from that date worked. Looking at the logs for that first failing backup on 1/6 and at the site, it looks like someone may have copied (moved if reports of top level folder existing recently are wrong) the data in that missing top level folder into a different top level folder. Our speculation is that perhaps that move happened during a backup.

Attached logs are from v. 0.19.0. I have logs from last successful backup and first v. 0.15.0 failed backup.

Corso Version?

Corso v0.15.0 and v0.19.0

Where are you running Corso?

Rocky linux 8.9, pointing at minio S3 on local TrueNAS.

Relevant log output

2024-04-26T18:27:13.341Z    INFO    operations/backup.go:330    completed backup    {"resource_owner_name": "cd8aa0a253f118ac", "tenant_id": "8775dbc38f6fed7a", "backup_id": "27de1a78-26af-42c2-b24a-8a8875241fe3", "categories": "[Libraries]", "resource_owner_selected": "https://contoso.sharepoint.com/sites/Safety", "resource_owner_id": "contoso.sharepoint.com,833bc6a0-aeae-4ce4-a7c6-239dc1cb3ddc,0c41cf0d-f00c-4940-a96a-7c14af1f5de7", "service": "SharePoint", "clues_trace": "c87ec511,87a1faf6,f7a9d5e7,535dcc0a,ddb4be11", "incremental": "true", "disable_assist_backup": "false", "results": {"startedAt":"2024-04-26T18:26:03.384118233Z","completedAt":"2024-04-26T18:27:13.341737293Z","backupID":"27de1a78-26af-42c2-b24a-8a8875241fe3","counts":null}, "failure": "running backup: persisting collection backups: building kopia directories: inflating collection tree: adding merge location: building updated location set: RepoRef already in matcher", "failureVerbose": "RepoRef already in matcher\n\t/home/runner/work/corso/corso/src/internal/kopia/merge_details.go:141\nbuilding updated location set\n\t/home/runner/work/corso/corso/src/internal/kopia/upload.go:844\nadding merge location\n\t/home/runner/go/pkg/mod/github.com/alcionai/clues@v0.0.0-20240125221452-9fc7746dd20c/err.go:668\ninflating collection tree\n\t/home/runner/work/corso/corso/src/internal/kopia/upload.go:1391\nbuilding kopia directories\n\t/home/runner/work/corso/corso/src/internal/kopia/wrapper.go:198\n\t/home/runner/work/corso/corso/src/internal/operations/backup.go:608\npersisting collection backups\n\t/home/runner/work/corso/corso/src/internal/operations/backup.go:488\nrunning backup\n\t/home/runner/work/corso/corso/src/internal/operations/backup.go:305"}
2024-04-26T18:27:13.342Z    INFO    logger/logger.go:602    [2024-04-26 18:26:00 +0000 UTC][C] 'corso.api_call': Count: 43 Sum: 43.000 LastUpdated: 2024-04-26 18:26:59.996346284 +0000 UTC m=+79.839783104
[2024-04-26 18:26:00 +0000 UTC][C] 'corso.api_call.200_OK': Count: 41 Sum: 41.000 LastUpdated: 2024-04-26 18:26:59.996348338 +0000 UTC m=+79.839785160
[2024-04-26 18:26:00 +0000 UTC][C] 'corso.api_call.x-ms-resource-unit': Count: 43 Sum: 43.000 LastUpdated: 2024-04-26 18:26:59.996358612 +0000 UTC m=+79.839795429
[2024-04-26 18:26:00 +0000 UTC][C] 'corso.api_call.410_Gone': Count: 2 Sum: 2.000 LastUpdated: 2024-04-26 18:26:16.445571576 +0000 UTC m=+36.289008393
[2024-04-26 18:26:00 +0000 UTC][S] 'corso.api_call': Count: 43 Min: 64.788 Mean: 998.341 Max: 1458.687 Stddev: 382.376 Sum: 42928.676 LastUpdated: 2024-04-26 18:26:59.996350295 +0000 UTC m=+79.839787114
[2024-04-26 18:26:00 +0000 UTC][S] 'corso.api_call.200_OK': Count: 41 Min: 64.794 Mean: 1038.176 Max: 1458.688 Stddev: 343.573 Sum: 42565.214 LastUpdated: 2024-04-26 18:26:59.996351732 +0000 UTC m=+79.839788549
[2024-04-26 18:26:00 +0000 UTC][S] 'corso.api_call.410_Gone': Count: 2 Min: 80.110 Mean: 181.814 Max: 283.518 Stddev: 143.831 Sum: 363.627 LastUpdated: 2024-04-26 18:26:16.445574112 +0000 UTC m=+36.289010929
    {"resource_owner_name": "cd8aa0a253f118ac", "clues_trace": "c87ec511,87a1faf6,f7a9d5e7", "resource_owner_selected": "https://contoso.sharepoint.com/sites/Safety", "resource_owner_id": "contoso.sharepoint.com,833bc6a0-aeae-4ce4-a7c6-239dc1cb3ddc,0c41cf0d-f00c-4940-a96a-7c14af1f5de7"}
2024-04-26T18:27:13.842Z    INFO    observe/observe.go:162  blocked flushing progress bars  {"clues_trace": "c87ec511,87a1faf6", "resource_owner_selected": "https://contoso.sharepoint.com/sites/Safety", "resource_owner_id": "contoso.sharepoint.com,833bc6a0-aeae-4ce4-a7c6-239dc1cb3ddc,0c41cf0d-f00c-4940-a96a-7c14af1f5de7", "resource_owner_name": "cd8aa0a253f118ac", "bar_count": 8}
2024-04-26T18:27:13.842Z    INFO    observe/observe.go:166  progress bars flushed   {"clues_trace": "c87ec511,87a1faf6", "resource_owner_selected": "https://contoso.sharepoint.com/sites/Safety", "resource_owner_id": "contoso.sharepoint.com,833bc6a0-aeae-4ce4-a7c6-239dc1cb3ddc,0c41cf0d-f00c-4940-a96a-7c14af1f5de7", "resource_owner_name": "cd8aa0a253f118ac"}
2024-04-26T18:27:13.842Z    INFO    observe/observe.go:121  resetting progress bars {"resource_owner_selected": "https://contoso.sharepoint.com/sites/Safety", "resource_owner_id": "contoso.sharepoint.com,833bc6a0-aeae-4ce4-a7c6-239dc1cb3ddc,0c41cf0d-f00c-4940-a96a-7c14af1f5de7", "resource_owner_name": "cd8aa0a253f118ac", "clues_trace": "c87ec511,87a1faf6", "bar_count": 0}
2024-04-26T18:27:13.842Z    ERROR   backup/backup.go:262    Backup 1 of 1 failed    {"error": "https://contoso.sharepoint.com/sites/Safety: running backup: persisting collection backups: building kopia directories: inflating collection tree: adding merge location: building updated location set: RepoRef already in matcher", "errorVerbose": "RepoRef already in matcher\n\t/home/runner/work/corso/corso/src/internal/kopia/merge_details.go:141\nbuilding updated location set\n\t/home/runner/work/corso/corso/src/internal/kopia/upload.go:844\nadding merge location\n\t/home/runner/go/pkg/mod/github.com/alcionai/clues@v0.0.0-20240125221452-9fc7746dd20c/err.go:668\ninflating collection tree\n\t/home/runner/work/corso/corso/src/internal/kopia/upload.go:1391\nbuilding kopia directories\n\t/home/runner/work/corso/corso/src/internal/kopia/wrapper.go:198\n\t/home/runner/work/corso/corso/src/internal/operations/backup.go:608\npersisting collection backups\n\t/home/runner/work/corso/corso/src/internal/operations/backup.go:488\nrunning backup\n\t/home/runner/work/corso/corso/src/internal/operations/backup.go:305\nhttps://contoso.sharepoint.com/sites/Safety\n\t/home/runner/work/corso/corso/src/cli/backup/backup.go:226", "error_labels": {}, "repo_ref": "{pb:0xc09b8b17e8 prefixElems:2}", "incremental": "true", "tenant_id": "8775dbc38f6fed7a", "assist_bases": "0", "collection_previous_location": "{pb:0xc09b8b17e8 prefixElems:2}", "collection_previous_path": "8775dbc38f6fed7a/sharepoint/06fd7af157b1743b/libraries/1007c07196276c90/470394db5d0d36df/5f50327c9fdd88fc/835798b95dae5679/679d4bac3e3c1ca8/04a45b50d10aeb14", "resource_owner_name": "cd8aa0a253f118ac", "merge_bases": "1", "collection_full_path": "8775dbc38f6fed7a/sharepoint/06fd7af157b1743b/libraries/1007c07196276c90/470394db5d0d36df/5f50327c9fdd88fc/d2a93b3da812bd3c/835798b95dae5679/d841b4cad7730b5e/04a45b50d10aeb14", "can_use_metadata": "true", "collection_count": "3091", "backup_id": "27de1a78-26af-42c2-b24a-8a8875241fe3", "snapshot_type": "item data", "collection_location": "5f50327c9fdd88fc/d2a93b3da812bd3c/835798b95dae5679/d841b4cad7730b5e/04a45b50d10aeb14", "can_use_previous_backup": "true", "disable_assist_backup": "false", "resource_owner_id": "contoso.sharepoint.com,833bc6a0-aeae-4ce4-a7c6-239dc1cb3ddc,0c41cf0d-f00c-4940-a96a-7c14af1f5de7", "resource_owner_selected": "https://contoso.sharepoint.com/sites/Safety", "service": "SharePoint", "collection_source": "operations", "clues_trace": "ea14f781", "categories": "[Libraries]"}
2024-04-26T18:27:13.969Z    ERROR   cli/cli.go:154  cli execution   {"error": "1 of 1 backups failed:\n∙ https://contoso.sharepoint.com/sites/Safety: running backup: persisting collection backups: building kopia directories: inflating collection tree: adding merge location: building updated location set: RepoRef already in matcher\n", "errorVerbose": "1 of 1 backups failed:\n∙ https://contoso.sharepoint.com/sites/Safety: running backup: persisting collection backups: building kopia directories: inflating collection tree: adding merge location: building updated location set: RepoRef already in matcher\n\n\t/home/runner/work/corso/corso/src/cli/backup/backup.go:266", "error_labels": {}, "clues_trace": "b12fc46f"}
heimdal-31 commented 5 months ago

2024-04-26T18-25-40Z.log Full debug log attached.

ntolia commented 5 months ago

As discussed on Discord, please try a new backup with v0.19 and --disable-incrementals.

heimdal-31 commented 5 months ago

Thank you! --disable-incrementals worked.