Juju backups failing Executor error: CappedPositionLost: CollectionScan died due to position in capped collection being deleted.

[Haw Loeung]

Hi,

When working on upgrading a controller from 2.5.1 to 2.6.10, we create a backup before hand. Unfortunately, this kept failing with:

| 2019-11-08T04:32:46.699+0000 done dumping logs.logs.82922af8-1adf-4425-8a5e-5ebdd26fbd03 (70806 documents); 2019-11-08T04:32:46.699+0000 writing juju.txns.log to ;
| 2019-11-08T04:32:46.963+0000 Failed: error reading collection: Executor error: CappedPositionLost: CollectionScan died due to position in capped collection being deleted. Last seen record id: RecordId(1197166037);

More details in https://pastebin.canonical.com/p/gCymqhdHbQ/ (Company private, sorry).

Thanks,

Haw

[Erlon R. Cruz (sombrafam)]

FYI, this is a mongodump bug that still open[1], so the approach I'm working on is just to
remove the capped collection from the dump. There's actually 1 used by juju: 'tnxs.log'

[1] https://jira.mongodb.org/browse/TOOLS-1636

[Felipe Reyes (freyes)]

> so the approach I'm working on is just to remove the capped collection from the dump. There's actually 1 used by juju: 'tnxs.log'

the txns collection most likely will contain in-flight transactions referenced by documents in their txn-queue property, when restoring from the backup jujud will get confused and my understanding is that it won't be able to commit changes until that out-of-sync gets sorted out (something that usually make us rely on mgopurge).

[Pen Gale (pengale)]

Dropping in some notes on voice and chat conversations so that they don't get lost down the line:

- We are working on migrating to Mongo 4 in the Juju 3.0 release. Per upstream, Mongo 4 probably doesn't have this issue.

- For Mongo 3, upstream has recommended that we "Consider using a TTL index to limit data size instead of a capped collection". We can look into that option if we aren't able to do the mongo upgrade for some reason.

- There do not seem to be workarounds in the meantime, other than doing the mongodb dump separately, without the collection that's causing trouble. Everything *should* work when you restore this mongodb to a fresh controller, but you won't be able to use the Juju backup tools in order to orchestrate, and we're not 100% certain that there won't be ill effects from losing the collection.

[Joseph Phillips (manadart)]

Observed this for a client cloud with the logs.logs collection.

[Soumya (trsoumi88)]

I have a periodic juju backup script which sometimes fails with a similar error. Pasting it here for reference.

----------------------------
ERROR while creating backup archive: while dumping juju state database: error dumping databases: error executing "/usr/bin/mongodump": 2021-04-19T07:05:31.665+0000 writing admin.system.users to ; 2021-04-19T07:05:31.667+0000 done dumping admin.system.users (2 documents); 2021-04-19T07:05:31.667+0000 writing admin.system.version to ; 2021-04-19T07:05:31.668+0000 done dumping admin.system.version (2 documents); 2021-04-19T07:05:31.669+0000 writing logs.logs.bac50024-0ebc-4409-8261-2cf17197e703 to ; 2021-04-19T07:05:31.669+0000 writing logs.logs.f11ecb98-49f4-4bbe-8990-b9ad8fcbf316 to ; 2021-04-19T07:05:31.669+0000 writing juju.txns.log to ; 2021-04-19T07:05:31.670+0000 writing juju.statuseshistory to ; 2021-04-19T07:05:31.828+0000 done dumping juju.statuseshistory (21524 documents); 2021-04-19T07:05:31.828+0000 writing juju.actions to ; 2021-04-19T07:05:31.832+0000 Failed: error writing data for collection `logs.logs.bac50024-0ebc-4409-8261-2cf17197e703` to disk: error reading collection: Executor error during find command: CappedPositionLost: CollectionScan died due to position in capped collection being deleted. Last seen record id: RecordId(95589716);
----------------------------

[John A Meinel (jameinel)]

One plausible fix would be to have 'juju create-backup --no-logs", as they
aren't usually super relevant to restore and usually consume a
significant amount of data.

On Tue, Apr 20, 2021 at 1:55 AM Soumya <email address hidden> wrote:

> I have a periodic juju backup script which sometimes fails with a
> similar error. Pasting it here for reference.
>
> ----------------------------
> ERROR while creating backup archive: while dumping juju state database:
> error dumping databases: error executing "/usr/bin/mongodump":
> 2021-04-19T07:05:31.665+0000 writing admin.system.users to ;
> 2021-04-19T07:05:31.667+0000 done dumping admin.system.users (2
> documents); 2021-04-19T07:05:31.667+0000 writing admin.system.version
> to ; 2021-04-19T07:05:31.668+0000 done dumping admin.system.version (2
> documents); 2021-04-19T07:05:31.669+0000 writing
> logs.logs.bac50024-0ebc-4409-8261-2cf17197e703 to ;
> 2021-04-19T07:05:31.669+0000 writing
> logs.logs.f11ecb98-49f4-4bbe-8990-b9ad8fcbf316 to ;
> 2021-04-19T07:05:31.669+0000 writing juju.txns.log to ;
> 2021-04-19T07:05:31.670+0000 writing juju.statuseshistory to ;
> 2021-04-19T07:05:31.828+0000 done dumping juju.statuseshistory (21524
> documents); 2021-04-19T07:05:31.828+0000 writing juju.actions to ;
> 2021-04-19T07:05:31.832+0000 Failed: error writing data for collection
> `logs.logs.bac50024-0ebc-4409-8261-2cf17197e703` to disk: error reading
> collection: Executor error during find command: CappedPositionLost:
> CollectionScan died due to position in capped collection being deleted.
> Last seen record id: RecordId(95589716);
> ----------------------------
>
> --
> You received this bug notification because you are subscribed to juju.
> Matching subscriptions: juju bugs
> https://bugs.launchpad.net/bugs/1852502
>
> Title:
> Juju backups failing Executor error: CappedPositionLost:
> CollectionScan died due to position in capped collection being
> deleted.
>
> To manage notifications about this bug go to:
> https://bugs.launchpad.net/juju/+bug/1852502/+subscriptions
>

[Haw Loeung (hloeung)]

On Tue, Apr 20, 2021 at 05:47:54PM -0000, John A Meinel wrote:
> One plausible fix would be to have 'juju create-backup --no-logs", as they
> aren't usually super relevant to restore and usually consume a
> significant amount of data.

Yes please. Perhaps --no-logs should be the default instead? So 'juju
create-backup' excludes logs by default, with an option such as
'--with-logs' or '--include-logs' for those wanting to also back up
logs.

Reducing the time it takes to perform Juju controller backups would
also be super useful to IS since we do this before performing any juju
upgrades (we run quite a lot of controllers and try to be as
up-to-date as possible).

[Haw Loeung (hloeung)]

I guess that falls under LP:1680683 - 'Poor "juju create-backup" performance'

[Erlon R. Cruz (sombrafam)]

> One plausible fix would be to have 'juju create-backup --no-logs", as they
> aren't usually super relevant to restore and usually consume a
> significant amount of data.

So, that would only reduce the set of problematic collections as there are other collections known
to fail (aka tnxs.log).

[John A Meinel (jameinel)]

It's fundamentally a race in how many changes happen while you are doing
the rest of the backup. If you can skip more of the actual content, then
the backup runs faster, giving less time for the data to overflow.

On Wed, May 19, 2021 at 10:30 AM Erlon R. Cruz <email address hidden>
wrote:

> > One plausible fix would be to have 'juju create-backup --no-logs", as
> they
> > aren't usually super relevant to restore and usually consume a
> > significant amount of data.
>
> So, that would only reduce the set of problematic collections as there are
> other collections known
> to fail (aka tnxs.log).
>
> --
> You received this bug notification because you are subscribed to juju.
> Matching subscriptions: juju bugs
> https://bugs.launchpad.net/bugs/1852502
>
> Title:
> Juju backups failing Executor error: CappedPositionLost:
> CollectionScan died due to position in capped collection being
> deleted.
>
> To manage notifications about this bug go to:
> https://bugs.launchpad.net/juju/+bug/1852502/+subscriptions
>

[Erlon R. Cruz (sombrafam)]

So, adding '--no-logs' would not be possible. Once you call mongodump with '--oplog' thats is what juju does[1], mongo only dumps the whole database, including all databases and tables. Can we revisit the need of using --oplog? It was not clear to me how this work and why juju needs it.

_________________
[1] mongodump -h 127.0.0.1 --port 37017 --ssl --sslAllowInvalidCertificates -u $agent -p $dbpass --authenticationDatabase admin --oplog

[John A Meinel (jameinel)]

Without --oplog you would have to take the Juju controllers offline to create a stable backup. Oplog allows you to start dumping the collections and include the write-ahead-log which means that if you start dumping collection A, by the time you get to collection Z, you have a consistent view across all of the collections.

It is interesting that with capped collections, we fundamentally have data that is fairly 'ephemeral' and would be ok if it wasn't consistent in the output. Certainly the option being discussed is to discard it entirely with '--no-logs'.

[nikhil kshirsagar (nkshirsagar)]

Adding some information on the bug as advised by John (@jam). A user who is hitting this has the following environment,

-$ juju --version
2.8.13-bionic-amd64

$ juju status
Model Controller Cloud/Region Version SLA Timestamp Notes
controller sj1-prod-maas-01-juju-controller maas_cloud 2.9.16 unsupported 09:49:29-08:00 upgrade available: 2.9.22

Machine State DNS Inst id Series AZ Message
0 started 10.100.40.233 kq34k7 bionic default Deployed
1 started 10.100.40.234 juju-2 bionic default Deployed
2 started 10.100.40.235 juju-3 bionic default Deployed

juju:PRIMARY> show databases
admin 0.000GB
backups 0.498GB
blobstore 0.454GB
config 0.000GB
juju 1.084GB
local 1.311GB
logs 0.205GB
juju:PRIMARY> show collections
system.keys
system.users
system.version
juju:PRIMARY>

They run a script to take daily backups of the juju controller and then a command to only keep the latest backup but the backups are filling up the disk on all the 3 juju controller nodes. I believe the script failure causes backups to keep piling up because the script to only keep the latest backup only runs upon successful backup.

even if they run this command manually they get the message that there is only most current backup.

# juju remove-backup -m sj1-prod-maas-01-juju-controller:admin/controller --keep-latest
WARNING no backups to remove, 20210921-190247.c06182d1-ffc0-454f-8418-dac55ad882a8 most current

But when they login into the controllers they see juju backup directories for every backup run in /tmp
:/tmp$ ls -ld jujuBackup*
drwx------ 3 root root 4096 Dec 20 10:58 jujuBackup-016549046
drwx------ 3 root root 4096 Dec 20 11:37 jujuBackup-042799675
drwx------ 3 root root 4096 Dec 20 10:58 jujuBackup-063462045
drwx------ 3 root root 4096 Dec 20 10:58 jujuBackup-270640115

These are the commands used

/snap/bin/juju create-backup -m sj1-prod-maas-01-juju-controller:admin/controller --filename $DEST_DIR/juju-backup-sj1-prod-maas-01-juju-controller-$TIME.tar.gz "sj1-prod-maas-01-juju-controller" 2>&1

juju remove-backup -m sj1-prod-maas-01-juju-
controller:admin/controller --keep-latest

[John A Meinel (jameinel)]

@nikhil are they running into "CappedPositionLost" or is it just that the temp directories are not being cleaned up? it sounds like a different bug, and I want to make sure we're trying to fix the right thing.

[John A Meinel (jameinel)]

So if they are running into CappedPositionLost there are a few things to investigate

We do have 2 configuration settings for how large the various capped collections are. There are 2 types in play
1) The txns.log which tracks recent transactions against the database, this can be tweaked with:
  `juju controller-config max-txn-log-size`
Essentially, it needs to be large enough that we can record any active transactions while the backup is being taken. It defaults to 10MB. That is an older setting, so I'm not sure if we support changing it (vs setting it on initial bootstrap). We can work with you to ensure that it both get set correctly and the database table is the right size.
https://docs.mongodb.com/manual/reference/command/convertToCapped/

2) log collections for each model also have a
  `juju controller-config model-log-size`

The default here is 20MB. This one does appear to be properly handled at startup. So if it is changed, restarting the controllers should apply the new collection size.

Some other thoughts:
a) I'm a bit concerned that with only 1GB of juju data and 200MB of log data, we're running into capped position lost. Something is happening at a very high churn rate, for a fairly small amount of data.

b) The backups collection isn't empty, it is at ~500MB, which for a 2.8 client and a 2.9 controller, I would expect that to be essentially empty, since we aren't saving anything into the database.
In fact, when I run 'juju create-backup' on a test 2.9 controller, I don't even have a 'backups' collection.

c) the 'juju' table being 1GB seems larger than I would expect given the other collection sizes. It is possible that there is a significant content in the database (lots of models/units/etc) but that doesn't match the idea that 'blobstore' that is holding all of the binaries for all deployed charms is only 500MB.

It would be good to get some information on the size breakdown. Is it possible to use

```
var collectionNames = db.getCollectionNames(), stats = [];
collectionNames.forEach(function (n) { stats.push(db[n].stats()); });
stats = stats.sort(function(a, b) { return b['size'] - a['size']; });
for (var c in stats) { print(stats[c]['ns'] + ": " + stats[c]['size'] + " (" + stats[c]['storageSize'] + ")"); }
```

One idea is that we might have a broken transaction document, causing us to spin trying to apply a new transaction, causing more churn that is causing a hiccup during backups.

I would expect to see log messages (available from `juju debug-log -m controller`, or introspective /var/log/juju/machine-* on a controller machine) complaining that it is failing to apply a transaction.

If that is an issue, it would be possible to stop the juju controllers (systemctl stop jujud-machine-* for any controller machine), and then run mgopurge to fix any obviously broken transactions.

[nikhil kshirsagar (nkshirsagar)]

The user has given the data collected by

```
var collectionNames = db.getCollectionNames(), stats = [];
collectionNames.forEach(function (n) { stats.push(db[n].stats()); });
stats = stats.sort(function(a, b) { return b['size'] - a['size']; });
for (var c in stats) { print(stats[c]['ns'] + ": " + stats[c]['size'] + " (" + stats[c]['storageSize'] + ")"); }
```

I'll upload the file to this bug.

I've also asked them for output of juju debug-log -m controller, and the /var/log/juju/machine-* on a controller machine.

Thank you for your help in this issue so far.

Regards,
Nikhil.

[John A Meinel (jameinel)]

Top entries from mongo output:
juju.txns 134MB, 189k entries
juju.metrics 126MB, 322k entries
juju.statuseshistory 84MB, 400k entries
juju.settings 22MB, 11k entries
juju.txns.log 10MB, 71k entries
juju.resources 46MB, 6k entries
juju.unitstates 3.1MB, 2.6k entries
juju.statuses 2.8MB, 11k entries

[John A Meinel (jameinel)]

juju.txns and juju.metrics seem a bit over sized. It isn't inherently a problem (it tries to be reasonable about how often we prune vs how much space is consumed), but it might hint at an issue if it is unable to prune an entry.

[nikhil kshirsagar (nkshirsagar)]

Hi John,

thank you for the comments and information. I've received the controller logs, and the /var/log/juju/machine-* ,

The controller debug logs are short, so I am pasting them here, there's just this much in that file,

------------------------------------------------------------------------------------

machine-2: 11:26:59 INFO juju.apiserver.common.networkingcommon processing link-layer devices for machine "298"
machine-2: 11:26:59 INFO juju.apiserver.common.networkingcommon processing link-layer devices for machine "15"
machine-2: 11:26:59 INFO juju.apiserver.common.networkingcommon processing link-layer devices for machine "18"
machine-2: 11:26:59 INFO juju.apiserver.common.networkingcommon processing link-layer devices for machine "200"
machine-2: 11:26:59 INFO juju.apiserver.common.networkingcommon processing link-layer devices for machine "40"
machine-2: 11:26:59 INFO juju.apiserver.common.networkingcommon processing link-layer devices for machine "388"
machine-2: 11:26:59 INFO juju.apiserver.common.networkingcommon processing link-layer devices for machine "267"
machine-2: 11:26:59 INFO juju.apiserver.common.networkingcommon processing link-layer devices for machine "300"
machine-2: 11:26:59 INFO juju.apiserver.common.networkingcommon processing link-layer devices for machine "75"
machine-2: 11:27:02 INFO juju.apiserver.common.networkingcommon processing link-layer devices for machine "410"

------------------------------------------------------------------------------------

I am attaching the other file collected - machine-0.log

Regards,
Nikhil.

[nikhil kshirsagar (nkshirsagar)]

Another user ran into this. We've received the requested data from them too, I will attach it to this bug.

In the machine logs, I see some link layer device merge attempts failing, like,

2022-01-25 14:23:59 ERROR juju.apiserver.instancepoller instancepoller.go:176 link layer device merge attempt for machine 121 failed due to error: provider IDs not unique: 507364; waiting until next instance-poller run to retry
2022-01-25 14:23:59 ERROR juju.apiserver.instancepoller instancepoller.go:176 link layer device merge attempt for machine 120 failed due to error: provider IDs not unique: 507379; waiting until next instance-poller run to retry

-Nikhil.

[Simon Richardson (simonrichardson)]

If we're seeing a lot of churn in logs.logs, maybe upping the log level to critical before the backup and then setting it back down to the previous state?

I'll speak with @jameinel today about this possible solution.

[Erlon R. Cruz (sombrafam)]

Hi folks, an important piece of information I forgot to past long ago when I hit this problem.
I was able to get rid of the errors by manually upgrading mongo from 3.6 to 4. This was a manual upgrade, and not recommended, but IFIK, juju 3 will bring mongo 4 so, the problem should be fixed there.

The tests I did was, first I setup an environment to reproduce the problem and measure the rate it was recurring. I used 4 vCPU 8GB VMs juju HA controller and had FIO running in the 3 controllers while I continuously took backups with mongodump. With mongo 3.6 I got the following failure rate:

Runs Failures
20 3
40 5
64 7
139 19

After I upgraded mongo to 4.X, there was not failures anymore even after 300 iterations and backups.
are faster as well.

[nikhil kshirsagar (nkshirsagar)]

Hi Simon,

thanks for the suggestion. Upping log level to critical and then back after taking the backup has helped avoid the issue. While the workaround does work, can we please get some idea of the long term fix, if any, or if we simply need to wait for juju 3.0 which would have mongo 4 which wouldnt have this issue?

Regards,
Nikhil.

[Haw Loeung (hloeung)]

On Thu, Apr 14, 2022 at 04:29:37AM -0000, nikhil kshirsagar wrote:
> thanks for the suggestion. Upping log level to critical and then back
> after taking the backup has helped avoid the issue. While the workaround
> does work, can we please get some idea of the long term fix, if any, or
> if we simply need to wait for juju 3.0 which would have mongo 4 which
> wouldnt have this issue?

Can Juju do that for us? As in, `juju create-backup` will
automatically up the log level to only log critical issues and then
back down once it's done creating a backup.

[John A Meinel (jameinel)]

I don't think it is something that makes sense for Juju to do by default, as the goal of backup is to not interrupt your normal flow.
Likely we also need to understand why a given model is generating that many logs in the first place. It sounds like something is in error and spinning and that error is just being ignored.

There are also some tools around rate limiting for logs that could also be tweaked here, though I don't think they are exposed in a clean fashion.
inside of agent.conf there is a section on 'values:' and you can set:
 LOGSINK_DBLOGGER_BUFFER_SIZE: 1000
 LOGSINK_DBLOGGER_FLUSH_INTERVAL: 2s
 LOGSINK_RATELIMIT_BURST: 1000
 LOGSINK_RATELIMIT_REFILL: 1ms

(those are the defaults).

The interesting ones are probably BURST and REFILL.
The general design is a token bucket, where every log message grabs a token as to whether it is allowed to be logged, and we refill that bucket as one token per time period.
So in the default config, any given agent can log up to 1000 messages as fast as they want, but they only get those back every 1ms. Which isn't very much rate limiting (it essentially means you can stream 1000 log messages per second indefinitely).
Changing it to either keep the burst fixed but drop the refill to 2ms or even 10ms, could be interesting.
There are a few other things:

a) *We* don't have a great feel for what is an appropriate stream of log messages that doesn't lose things you care about but does avoid overloading. So working with us to help find reasonable defaults.

b) We really should expose these as `juju controller-config` rather than being hidden in agent.conf. (The code to handle rate limiting predates our support for controller-config.)

c) We *might* want to also have a total rate limiting, or a per-model rate limiting (those do get trickier because you have to share the rate limiting bucket between threads.)

[Joseph Phillips (manadart)]

Something that might be worth entertaining for these scenarios is to use the logging-output configuration article.

You can direct logging to syslog instead of Mongo by using the config:
"logging-output=syslog"

On 2.9 this is behind a feature flag, so you will also need to configure:
"features=[logging-output]"

The flag won't be required for 3.0.

Just be aware that depending on the specific environment, using this feature can cause a lot of logging via the serial console. It caused issues on one particularly large controller.

[Erlon R. Cruz (sombrafam)]

Hey Joseph, thanks for the hint. Do you have the full CLI you used? I tried first on juju 2.9.27, but this was added on 2.9.29 (I can see from the code). But still, even after upgrading, it seems that there's no 'features' config in the allowed configs:

juju model-config "features=[logging-output]"
WARNING key "features" is not defined in the current model configuration: possible misspelling
ERROR cannot set controller attribute "features" on a model

[Haw Loeung (hloeung)]

I believe that's `juju controller-config` rather than `model-config`.

`juju help controller-config` says:

| features:
| type: list
| description: A list of runtime changeable features to be updated

[Erlon R. Cruz (sombrafam)]

Thanks Haw,

So, for future travelers here is how I manage to make juju to log to syslog:

juju controller-config "features=[logging-output]"
juju model-config -m controller logging-output=syslog
# restart the juju services in the controller

Logs can be seen on /var/log/syslog and journalctl -afu juju*

[Haw Loeung (hloeung)]

Thanks for that.

Interestingly, do you have metrics for the change switching to syslog for logging? Wondering if it helps reduce MongoDB load (in particular I/O). If so, how much in terms of percentage?

[Erlon R. Cruz (sombrafam)]

I don't have any metrics for that but removing the load from MongoDB and moving it to syslog will not make a huge difference since you still is doing the IO in the same device. The nice thing about that is that you could use another partition/disk to have the log data, then you would have one disk only for log operations.

But, if you want to have gains on that, you could just decrease the logging level to WARNING or ERROR only. That alone will immensely decrease you controller load.

[Aliaksandr Vasiuk (valexby)]

Hi,

We faced this issue again today. And it appeared that there is a more straightforward workaround available - just rerun this command couple of times and it works. And Bootstack team has used this approach successfully for some time. We got this output today
```
$juju create-backup
ERROR while creating backup archive: while dumping juju state database: error dumping databases: error executing "/usr/bin/mongodump": 2022-11-16T13:50:06.601+0000 writing admin.system.users to ; 2022-11-16T13:50:06.602+0000 done dumping admin.system.users (4 documents); 2022-11-16T13:50:06.603+0000 writing admin.system.version to ; 2022-11-16T13:50:06.604+0000 done dumping admin.system.version (2 documents); 2022-11-16T13:50:06.605+0000 writing juju.statuseshistory to ; 2022-11-16T13:50:06.605+0000 writing logs.logs.d8f110a4-7bdd-48b8-8231-72af1152f2a8 to ; 2022-11-16T13:50:06.606+0000 writing logs.logs.667d1c03-b40a-4836-8a09-645f5b83da44 to ; 2022-11-16T13:50:06.606+0000 writing juju.txns.log to ; 2022-11-16T13:50:07.465+0000 done dumping logs.logs.d8f110a4-7bdd-48b8-8231-72af1152f2a8 (78230 documents); 2022-11-16T13:50:07.465+0000 writing logs.logs.1d5c3328-ea4a-4fda-830c-6d25724e8140 to ; 2022-11-16T13:50:07.697+0000 Failed: error writing data for collection `juju.txns.log` to disk: error reading collection: Executor error during find command: CappedPositionLost: CollectionScan died due to position in capped collection being deleted. Last seen record id: RecordId(39255325);
```
And after that we tried a couple more times to run `$ juju create-backup` and it worked.