juju.worker.dependency engine.go:539 "mgo-txn-resumer" manifold worker returned unexpected error: cannot resume transactions: cannot find transaction ObjectIdHex("stuff")

Relevant logs at : https://private-fileshare.canonical.com/~axino/lp1643795

If you need anything, please let me know, thanks !

This means that MongoDB has managed to lose data and some of the lost data is mgo/txn's transaction bookkeeping data. This means that no transaction can run.

The reason for the 55000 txn-queue entries on that document is that a transaction affects that document every 30s or so but because no transactions can currently complete so pending transactions are building up.

The only solution is to shut down the controller machine agent and run mgopurge. Please make sure you use the latest version from https://github.com/juju/mgopurge. Some important fixes were made to mgopurge last week.

If you need someone to build mgopurge for you and send you the binary let me know.

@Junien,
There is a detailed step-by-step guide on how to run mgopurge on https://github.com/juju/juju/wiki/Incomplete-Transactions-and-MgoPurge.

Please reach out if you have further questions!

Hi,

I'll take a look at mgopurge. In the meantime, shouldn't juju be able to handle these errors more gracefully ? If you have a wiki page describing how to recover from a lost transaction, I guess this is not a rare problem.

Having an unreponsive controller that is overloading the CPU is not a good experience IMO, even if the root cause is not juju itself.

So I ran mgopurge (which I built from github), and it worked. Then I started the machine agent, and it's still using ~150-200% CPU with no good reason. I can't get an answer to "juju status". I can see the other agents attempting to connect, only to be met with :

{"request-id":1,"error":"login for \"unit-nrpe-0\" blocked because upgrade in progress","response":"'body redacted'"} Admin[""].Login

The first document in the "leases" collection now has around 155k IDs in txn-queue. I stopped jujud-machine-0 as I don't want it to grow more.

Full logs are at https://private-fileshare.canonical.com/~axino/lp1643795/2/

Did mgopurge indicate that it fixed some issues?

The high CPU and lack of responsiveness is possibly because the machine agent is busy processing all those backed up transactions. If left for a while things might return to normal.

Can you start up the machine agent and monitor the counts of documents in txns collection with a "s" field (state) of 5 or 6 (aborted or completed) vs those with other state values? You should see transactions steadily moving to aborted or completed (mostly completed).

Never mind my question above. I see from the mgopurge output you linked to that mgopurge did indeed correct some transaction data for leases collection. That's good.

Based on the tail of the mongodb and machine agent logs you've provided, the machine agent is looking reasonably healthy and the it appears to be churning through all those backed up transactions. Giving the machine agent some time to process through them seems like the right approach.

OK, it's back up. I'll let you know how it goes.

Another argument for stopping the machine agent (or "soft stopping" it, i.e. put it in frozen mode or something) is that you then don't have transactions getting queued and needing to be processed whenever the DB is back to OK.

Is there any way I can measure the progress of the recovery ? It's been nearly a day...

So after "just" maxxing out the CPUs for a while, juju starts taking up all the memory, and the machine becomes basically useless.

I can see the classic "2016-11-24 10:27:18 ERROR juju.worker.dependency engine.go:539 "disk-manager" manifold worker returned unexpected error: cannot list block devices: lsblk failed: fork/exec /bin/lsblk: cannot allocate memory" in the logs.

I have TRACE level logs of this happening in https://private-fileshare.canonical.com/~axino/lp1643795/3/

I'm going to have to tear down the environment tomorrow though. I guess replicating the disappearance of a mongo document is easy enough to replicate if you need further testing.

This work, whilst desirable, will not happen until later stage, post-2.3. I am triaging this back into wishlist.

Current workaround, when these log messages appear is to run mgopurge.

Hey, so this bug is regularly causing outages for us and wakes people up at weekends. Wishlist is a very hostile status for people trying to use Juju in production.

We have changes in mgopurge v1.4 (released today) and Juju 2.2 (out soon) which make significant improvement to the way txns are pruned. This makes massively reduces the amount of txn data that Juju has to track, reducing the scope for txn corruption.

This bug has not been updated in 2 years, so we're marking it Low importance. If you believe this is incorrect, please update the importance.