# Restore Fails with Demultiplexing failure

**URL:** <https://forums.percona.com/t/restore-fails-with-demultiplexing-failure/13709>\
**Category:** Percona Backup for MongoDB\
**Created:** [December 30, 2021, 12:59pm UTC](https://forums.percona.com/t/restore-fails-with-demultiplexing-failure/13709 "2021-12-30T12:59:49Z")\
**Posts on this page:** 4\
**Page:** 1

<div class="post-metadata">

**Author:** ![TimSandberg](https://sea1.discourse-cdn.com/flex019/user_avatar/forums.percona.com/timsandberg/32/3322_2.png) [@TimSandberg](https://forums.percona.com/u/TimSandberg)\
**Post date:** [December 30, 2021, 12:59pm UTC](https://forums.percona.com/t/restore-fails-with-demultiplexing-failure/13709/1 "2021-12-30T12:59:49Z")

</div>

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?

---

<div class="post-metadata">

**Author:** ![jenunes](https://sea1.discourse-cdn.com/flex019/user_avatar/forums.percona.com/jenunes/32/9331_2.png) [@jenunes](https://forums.percona.com/u/jenunes)\
**Post date:** [December 30, 2021, 11:07pm UTC](https://forums.percona.com/t/restore-fails-with-demultiplexing-failure/13709/2 "2021-12-30T23:07:19Z")

</div>

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](https://jira.percona.com/browse/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,

---

<div class="post-metadata">

**Author:** ![TimSandberg](https://sea1.discourse-cdn.com/flex019/user_avatar/forums.percona.com/timsandberg/32/3322_2.png) [@TimSandberg](https://forums.percona.com/u/TimSandberg)\
**Post date:** [January 3, 2022, 4:58pm UTC](https://forums.percona.com/t/restore-fails-with-demultiplexing-failure/13709/3 "2022-01-03T16:58:55Z")

</div>

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

---

<div class="post-metadata">

**Author:** ![TimSandberg](https://sea1.discourse-cdn.com/flex019/user_avatar/forums.percona.com/timsandberg/32/3322_2.png) [@TimSandberg](https://forums.percona.com/u/TimSandberg)\
**Post date:** [January 4, 2022, 2:29am UTC](https://forums.percona.com/t/restore-fails-with-demultiplexing-failure/13709/4 "2022-01-04T02:29:24Z")

</div>

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.
