Restore Fails with Demultiplexing failure

[TimSandberg]

I’m now attempting to restore to the new testing server and I keep getting the following error when attempting to do so:

error restoring from archive on stdin: reading bson input: error demultiplexing archive; archive io error

I’ve received this error with multiple backups and I’m restoring from S3 to a server that only has 4 GB of RAM. Is this a resource issue with the server or are my backups really corrupted?

[jenunes]

Hi @TimSandberg,

Which version of PBM are you using? That will help us check if you are hitting any possible issue, for example: PBM-555.

Additionally; Is the issue also happening on backup executions or only during the restores? Have you tried testing with a different backup location? Does it happen with all snapshots to restore?

If possible, could you please try changing the backup location and validate if the same issue happens?

More details about the problem and configuration will help understand the case correctly; Please also add the pbm log for additional review.

Best,

[TimSandberg]

PBM-555 is definitely the same issue I’m having, however, I’m on version 1.6.1. Output from pbm version:
Version: 1.6.1
Platform: linux/amd64
GitCommit: aebbc24a03f21f9ddee6ebb72f510ff1d1c58fdc
GitBranch: release-1.6.1
BuildTime: 2021-11-03_12:09_UTC
GoVersion: go1.16.9

I’m backing up our primary mongo cluster and restoring it to a test cluster to verify the backups are complete and working (good thing, eh?). I’ve tried several different snapshots over a 30 day timeframe and continually receive the same issue. I also added a 20GB swap space to the test cluster to ensure that it wasn’t an out-of-memory issue. Here is the output from pbm log:

2022-01-03T15:24:23Z W [mongo-prod-set/127.0.0.1:27017] [restore/2021-12-20T20:00:01Z] io.copy: context deadline exceeded (Client.Timeout or context cancellation while reading body)
2022-01-03T15:24:24Z W [mongo-prod-set/127.0.0.1:27017] [restore/2021-12-20T20:00:01Z] got context deadline exceeded (Client.Timeout or context cancellation while reading body), try to reconnect in 5s
2022-01-03T15:24:29Z I [mongo-prod-set/127.0.0.1:27017] [restore/2021-12-20T20:00:01Z] session recreated, resuming download
2022-01-03T15:25:30Z W [mongo-prod-set/127.0.0.1:27017] [restore/2021-12-20T20:00:01Z] io.copy: context deadline exceeded (Client.Timeout or context cancellation while reading body)
2022-01-03T15:25:31Z W [mongo-prod-set/127.0.0.1:27017] [restore/2021-12-20T20:00:01Z] got context deadline exceeded (Client.Timeout or context cancellation while reading body), try to reconnect in 6s
2022-01-03T15:25:38Z I [mongo-prod-set/127.0.0.1:27017] [restore/2021-12-20T20:00:01Z] session recreated, resuming download
2022-01-03T15:26:39Z W [mongo-prod-set/127.0.0.1:27017] [restore/2021-12-20T20:00:01Z] io.copy: context deadline exceeded (Client.Timeout or context cancellation while reading body)
2022-01-03T15:26:40Z W [mongo-prod-set/127.0.0.1:27017] [restore/2021-12-20T20:00:01Z] got context deadline exceeded (Client.Timeout or context cancellation while reading body), try to reconnect in 7s
2022-01-03T15:26:47Z I [mongo-prod-set/127.0.0.1:27017] [restore/2021-12-20T20:00:01Z] session recreated, resuming download
2022-01-03T15:27:53Z W [mongo-prod-set/127.0.0.1:27017] [restore/2021-12-20T20:00:01Z] io.copy: context deadline exceeded (Client.Timeout or context cancellation while reading body)
2022-01-03T15:27:54Z W [mongo-prod-set/127.0.0.1:27017] [restore/2021-12-20T20:00:01Z] got context deadline exceeded (Client.Timeout or context cancellation while reading body), try to reconnect in 8s
2022-01-03T15:28:03Z I [mongo-prod-set/127.0.0.1:27017] [restore/2021-12-20T20:00:01Z] session recreated, resuming download
2022-01-03T15:29:07Z W [mongo-prod-set/127.0.0.1:27017] [restore/2021-12-20T20:00:01Z] io.copy: context deadline exceeded (Client.Timeout or context cancellation while reading body)
2022-01-03T15:29:07Z W [mongo-prod-set/127.0.0.1:27017] [restore/2021-12-20T20:00:01Z] got context deadline exceeded (Client.Timeout or context cancellation while reading body), try to reconnect in 9s
2022-01-03T15:29:17Z I [mongo-prod-set/127.0.0.1:27017] [restore/2021-12-20T20:00:01Z] session recreated, resuming download
2022-01-03T15:30:17Z W [mongo-prod-set/127.0.0.1:27017] [restore/2021-12-20T20:00:01Z] io.copy: context deadline exceeded (Client.Timeout or context cancellation while reading body)
2022-01-03T15:30:17Z W [mongo-prod-set/127.0.0.1:27017] [restore/2021-12-20T20:00:01Z] got context deadline exceeded (Client.Timeout or context cancellation while reading body), try to reconnect in 10s
2022-01-03T15:30:28Z I [mongo-prod-set/127.0.0.1:27017] [restore/2021-12-20T20:00:01Z] session recreated, resuming download
2022-01-03T15:30:28Z E [mongo-prod-set/127.0.0.1:27017] [restore/2021-12-20T20:00:01Z] download ‘gc-backups-prod/2021-12-20T20:00:01Z_mongo-prod-set.dump.gz’ file from S3: context deadline exceeded (Client.Timeout or context cancellation while reading body)
2022-01-03T15:30:28Z E [mongo-prod-set/127.0.0.1:27017] [restore/2021-12-20T20:00:01Z] restore: mongorestore: restore mongo dump (successes: 3461404 / fails: 0): GC.AuditLog-a-bot2: error restoring from archive on stdin: reading bson input: error demultiplexing archive; archive io error

[TimSandberg]

So this turns out to be a resource issue. I was originally trying to restore using a 2 CPU/4GB RAM VM, but decided to experiment with it. I created a new VM with 4 CPU/8GB RAM and was able to successfully restore. I did notice during the restore when I received a “got context deadline exceeded (Client.Timeout or context cancellation while reading body), try to reconnect” error message, pbm-agent was using > 50% of the available RAM. Fortunately, one of the collections finished restoring and memory usage dropped back to normal levels.