Juju's mongodb does not need to log every command in syslog

Amongst other things, every log entry is a potential hit to the disk we don't need.

This *might* be a debug setting that Landscape is invoking, if I look at
ps output on all these machines it's like this:

ubuntu@maas-1-04:/var/log/juju$ ps ax | grep juju
 8412 ? Ssl 0:07 /var/lib/juju/tools/machine-0/jujud machine
--data-dir /var/lib/juju --machine-id 0 --debug
10036 ? Ss 0:00 lxc-start --daemon -n juju-machine-0-lxc-0 -c
/var/lib/juju/containers/juju-machine-0-lxc-0/console.log -o
/var/lib/juju/containers/juju-machine-0-lxc-0/container.log -l DEBUG
10258 pts/2 S+ 0:00 grep --color=auto juju
10945 ? Ss 0:00 lxc-start --daemon -n juju-machine-0-lxc-1 -c
/var/lib/juju/containers/juju-machine-0-lxc-1/console.log -o
/var/lib/juju/containers/juju-machine-0-lxc-1/container.log -l DEBUG
11845 ? Ssl 2:25 /var/lib/juju/tools/machine-0-lxc-0/jujud
machine --data-dir /var/lib/juju --machine-id 0/lxc/0 --debug
11926 ? Ss 0:00 lxc-start --daemon -n juju-machine-0-lxc-2 -c
/var/lib/juju/containers/juju-machine-0-lxc-2/console.log -o
/var/lib/juju/containers/juju-machine-0-lxc-2/container.log -l DEBUG
12034 ? Ssl 2:15 /var/lib/juju/tools/unit-glance-0/jujud unit
--data-dir /var/lib/juju --unit-name glance/0 --debug
12541 ? Ssl 2:23 /var/lib/juju/tools/machine-0-lxc-1/jujud
machine --data-dir /var/lib/juju --machine-id 0/lxc/1 --debug

All the --debug's might be causing the traffic. Even so, perhaps we
should steer that to /var/log/juju/db.log rather than syslog? Perhaps
errors would still go to syslog regardless?

Mark

Landscape doesn't invoke any debug settings so it would be from something else.

Could it be because I've jimmied it to use the testing (1.20.2-current)
tools?

Mark

Isn't this a dupe of bug 1365828?

This is still getting me on 1.23 beta2:

just one minute of activity:

Apr 6 10:02:02 helo mongod.37017[3589]: Mon Apr 6 10:02:02.604 [conn19] authenticate db: admin { authenticate: 1, nonce: "cea743763679c26a", user: "machine-0", key: "659bc01b901d62420553c328f3e691eb" }
Apr 6 10:02:03 helo mongod.37017[3589]: Mon Apr 6 10:02:03.861 [conn11] authenticate db: admin { authenticate: 1, nonce: "1bac715cfb638039", user: "machine-0", key: "eb382d39e4209da08e9f5d7c0f8060d5" }
Apr 6 10:02:07 helo mongod.37017[3589]: Mon Apr 6 10:02:07.319 [conn11] authenticate db: admin { authenticate: 1, nonce: "6057d4eda32492da", user: "machine-0", key: "b65a72089b4fe9436c73b77ea7613204" }
Apr 6 10:02:18 helo mongod.37017[3589]: Mon Apr 6 10:02:18.827 [conn11] authenticate db: admin { authenticate: 1, nonce: "c86b3e796bf3498a", user: "machine-0", key: "72fe8ef1d789a5f815ab068ea8b59064" }
Apr 6 10:02:30 helo mongod.37017[3589]: Mon Apr 6 10:02:30.330 [conn11] authenticate db: admin { authenticate: 1, nonce: "563f1e0b0de2bd51", user: "machine-0", key: "202dadd421e6800e51da866a37b8c84f" }
Apr 6 10:02:32 helo mongod.37017[3589]: Mon Apr 6 10:02:32.604 [conn19] authenticate db: admin { authenticate: 1, nonce: "b2520cc7eb643fba", user: "machine-0", key: "f4ba949015ffdea8662698612b5381f6" }
Apr 6 10:02:32 helo mongod.37017[3589]: Mon Apr 6 10:02:32.606 [conn11] authenticate db: admin { authenticate: 1, nonce: "cf101f2c2e59195c", user: "machine-0", key: "20b4f43967d545fa8fc220b95dfbff6b" }
Apr 6 10:02:37 helo mongod.37017[3589]: Mon Apr 6 10:02:37.211 [conn11] authenticate db: admin { authenticate: 1, nonce: "6ae92e2ac1867394", user: "machine-0", key: "63c0e38d06b46747e585eba9983d1305" }
Apr 6 10:02:43 helo mongod.37017[3589]: Mon Apr 6 10:02:43.158 [conn11] authenticate db: admin { authenticate: 1, nonce: "4e99491cd212b735", user: "machine-0", key: "e6189aa100ca093ff102b37d5f096463" }
Apr 6 10:02:51 helo mongod.37017[3589]: Mon Apr 6 10:02:51.073 [conn11] authenticate db: admin { authenticate: 1, nonce: "d78380bff3c1f83e", user: "machine-0", key: "1cba1f4b82398c64ad29669a3c67a0d2" }
Apr 6 10:02:52 helo mongod.37017[3589]: Mon Apr 6 10:02:52.508 [conn11] authenticate db: admin { authenticate: 1, nonce: "8963cbb

With an idle juju local provider without even anything deployed! :(

Ideas from Casey:

<snip>
There's a few things we could try. The --quiet option might improve
things -- also setting `systemLog.verbosity` to a low value (maybe
start with 0 or 1). I wasn't able to reproduce the messages on a recent
version of Juju (so maybe we can mark it invalid?) but I'd try to rule
that out first, due to the names on this bug.

I've also seen some suggestion that rsyslog filters could be used
(https://groups.google.com/forum/#!topic/mongodb-user/BASDecriSOA) but
not sure if that's workable.

A last resort might be to just send the log to a separate file, so it at
least stops spamming the syslog. A logrotate config could be added to
keep it from growing too large.

I can confirm this still happening in 1.24 alpha, tested on a maas.

We will need to address this by adding a filter to rsyslog, the origin of the issue lies in mongo:
I has been present for quite some time: http://grokbase.com/t/gg/mongodb-user/13bpfds4xr/mongod-logging-noisy-even-with-quiet-flag
They eventually adressed it: https://jira.mongodb.org/browse/SERVER-5952
and it will be out for 2.8 or 3.1.2 : https://github.com/mongodb/mongo/commit/4949daa51bbd5104d666082e968e6dd81c22f2bd

Juju requires a newer version of mongodb to address this issue, one that supports the quiet flag. We can see that the packages with the required version do not exist yet in.
    http://www.mongodb.org/dl/linux/x86_64-ubuntu1404

There is nothing that can be done. The fix described in comment #9 looks like a feature, not a bug fix and many not be considered viable as a patch against mongodb 2.6.

Juju Core will need to select a version of mongodb and ask foundations to include in Wiley, Juju will also require that same version to be packaged as juju-db so that it can be backported to Trusty, and possibly Vivid. We will probably ignore Utopic.

Note that in a customer site with HA=3 and ~100 machines we are seeing syslog grow to around 3.6GB before it gets rotated (presumably daily?). Which means that we end up consuming 7.2GB just before the second rotation, and most of it is going to be these fairly useless logging output.
I believe we can filter out some of these messages. Ideally with a way to turn that filtering off quickly in case you really do want to debug authentication issues.

Also, it would be good to know why we are authenticating so often. It certainly seems far too often.

I had to add these to the top of /etc/rsyslog.d/50-default.conf to silence things:

:msg, contains, "warning: No such role, \"clusterAdmin\"" ~
:msg, contains, "warning: No such role, \"readWriteAnyDatabase\"" ~
:msg, contains, "authenticate db:" ~

Can we put that fragment in the jujud blob, so it's installed when Juju is installed? 99-jujud.conf might be a better name for it.

The code which sets up the role lives here:

https://github.com/juju/juju/blame/8da94246468a4da71e62894f7a8a1bbbce112697/mongo/admin.go#L136

The roles we are setting up are:

    Roles: []mgo.Role{
        mgo.RoleDBAdminAny,
        mgo.RoleUserAdminAny,
        mgo.RoleClusterAdmin,
        mgo.RoleReadWriteAny},

Why do we need RoleClusterAdmin and RoleReadWriteAny (in particular, because they don't seem to be defined in the database)?

On 28/07/15 18:26, Christian Reis wrote:
> The code which sets up the role lives here:
>
> https://github.com/juju/juju/blame/8da94246468a4da71e62894f7a8a1bbbce112697/mongo/admin.go#L136
>
> The roles we are setting up are:
>
> Roles: []mgo.Role{
> mgo.RoleDBAdminAny,
> mgo.RoleUserAdminAny,
> mgo.RoleClusterAdmin,
> mgo.RoleReadWriteAny},
>
> Why do we need RoleClusterAdmin and RoleReadWriteAny (in particular,
> because they don't seem to be defined in the database)?
>

They are not in 2.4 but are in 2.6+. Some time back, Juju was ported to be
compatible with mongo 2.6+ as a pre-requisite to allowing upgrading to a more
recent mongo (there are bugs not fixed in 2.4). However, the effort to get Juju
on mongo 2.6 was then stalled because of the tokumx evaluation.

Can someone please describe what work needs doing against the mongodb task here, please? And is the juju-mongodb package relevant here? If you need a newer version, which version do you need exactly?

It might be worth updating the bug description to describe the current plans to fix this bug, as there are a number of options described in the comments and it isn't clear to me what the plan is or what bug tasks track what actions.

We are getting over 10K messages from mongoDB, specially with the TXN collection.

Oct 7 08:57:17 xxx mongod.37017[1097]: Wed Oct 7 08:57:17.357 [xxx] warning: log line attempted (38k) over max size(10k), printing beginning and end ... remove juju.txns query: { _id: { $in: [ ObjectId('5614b19f4c860d58fe00d3d8'), ObjectId('5614d39d4c860d58fe00f5e2'), ObjectId('5614d5f34c860d58fe00f835'), ObjectId('5614dc664c860d58fe00fea9'), ObjectId('5614aa1c4c860d58fe00cc54'), ObjectId('5614b2184c860d58fe00d450'), ObjectId('5614de2a4c860d58fe01006f'), ObjectId('5614dd1e4c860d58fe00ff67'), ObjectId('5614a6de4c860d58fe00c920'), ObjectId('5614b1294c860d58fe00d368'), ObjectId('5614d59e4c860d58fe00f7e7'), ObjectId('5614d9044c860d58fe00fb4d'), ObjectId('5614b9414c860d58fe00db83'), ObjectId('5614d8c74c860d58fe00fb0e'), ObjectId('5614ddc44c860d58fe010003'), ObjectId('5614a7724c860d58fe00c9b5'), ObjectId('5614ab424c860d58fe00cd7d'), ObjectId('5614ac3f4c860d58fe00ce80'), ObjectId('5614ad044c860d58fe00cf3f'), ObjectId('5614ad844c860d58fe00cfbf'), ObjectId('5614d0ca4c860d58fe00f30a'), ObjectId('5614d40b4c860d58fe00f64c'), ObjectId('5614d8074c860d58fe00fa48'), ObjectId('5614bf584c860d58fe00e198'), ObjectId('5614a70b4c860d58fe00c946'), ObjectId('5614b09e4c860d58fe00d2db'), ObjectId('5614abfe4c860d58fe00ce39'), ObjectId('5614bac94c860d58fe00dd0c'), ObjectId('5614c2804c860d58fe00e4be'), ObjectId('5614ab444c860d58fe00cd7f'), ObjectId('5614bcc14c860d58fe00defe'), ObjectId('5614c49f4c860d58fe00e6e4'), ObjectId('5614cd0b4c860d58fe00ef4c'), ObjectId('5614ce1b4c860d58fe00f060'), ObjectId('5614d4504c860d58fe00f693'), ObjectId('5614af274c860d58fe00d15f'), ObjectId('5614a8034c860d58fe00ca3e'), ObjectId('5614afc04c860d58fe00d1ff'), ObjectId('5614afe34c860d58fe00d225'), ObjectId('5614b8434c860d58fe00da7c'), ObjectId('5614be644c860d58fe00e0a0'), ObjectId('5614b5234c860d58fe00d75f'), ObjectId('5614b5334c860d58fe00d76f'), ObjectId('5614d2af4c860d58fe00f4f5'), ObjectId('5614b77f4c860d58fe00d9c0'), ObjectId('5614c9ff4c860d58fe00ec41'), ObjectId('5614d2c44c860d58fe00f504'), ObjectId('5614d46e4c860d58fe00f6b1'), ObjectId('5614d0af4c860d58fe00f2f3'), ObjectId('5614a6624c860d58fe00c886'), ObjectId('5614ba624c860d58fe00dc9e'), ObjectId('5614d88f4c860d58fe00fad7'), ObjectId('5614bf894c860d58fe00e1c5'), ObjectId('5614abf64c860d58fe00ce30'), ObjectId('5614bfd24c860d58fe00e214'), ObjectId('5614b3d64c860d58fe00d60f'), ObjectId('5614c0af4c860d58fe00e2eb'), ObjectId('5614c8424c860d58fe00ea8a'), ObjectId('5614c8624c860d58fe00eaaa'), ObjectId('5614ce8c4c860d58fe00f0cc'), ObjectId('5614d8524c860d58fe00fa9a'), ObjectId('5614dabc4c860d58fe00fcfc'), ObjectId('5614c8d64c860d58fe00eb1c'), ObjectId('5614c2f84c860d58fe00e536'), ObjectId('5614ccd24c860d58fe00ef18'), ObjectId('5614c7714c860d58fe00e9b3'), ObjectId('5614c5ca4c860d58fe00e810'), ObjectId('5614c9c64c860d58fe00ec0c'), ObjectId('5614cdc24c860d58fe00f008'), ObjectId('5614cd854c860d58fe00efc9'), ObjectId('5614da2d4c860d58fe00fc71'), ObjectId('5614c2714c860d58fe00e4ad'), ObjectId('5614c41a4c860d58fe00e656'), ObjectId('5614c6054c860d58fe00e849'), ObjectId('5614c6254c860d58fe00e869'), ObjectId('5614d6264c860d58fe00f866'), ObjectId('5614daa24c860d58fe00fce2...

I believe the fix here is in the work to rev to mongo 3.0 or 3.2 in 16.04.

Mark

This is still affecting us on 1.25.3.

Paul, I believe the plan is to move to MongoDB 3.2 with Juju 2.0, which
solves the issue. I am not sure when we will have an upgrade mechanism
from 1.x to 2.x but we intend to do that in due course.

Mark

I also have logspam with thrashing, but in addition to the "authenticate db:" lines I also get ones that look like variables are breaking through juju, with $cmd written in the log instead of the actual value of $cmd.

Mar 16 20:50:36 localhost mongod.37017[5355]: Wed Mar 16 20:50:36.399 [conn20] command juju.$cmd command: { getLastError: 1, j: true } ntoreturn:1 keyUpdates:0 reslen:101 313ms

Tons of these, so I used the workaround provided above...

:/etc/rsyslog.d# cat 00-ignore-mongo-spam.conf
#
# juju bug #1349949 workaround
#
:msg, contains, "authenticate db: " stop
:msg, contains, "command presence.\$cmd command" stop
:msg, contains, "command juju.\$cmd command" stop

That fully fixes my logspam for juju 1.25.3-wily-amd64

And from MAAS it can be done by adding the following to /etc/maas/preseeds/curtin_userdata

late_commands:
  mongo_01: curtin in-target -- sh -c '/bin/echo :msg, contains, \"authenticate db:\" \~ >> /etc/rsyslog.d/16-mongohush.conf'
  mongo_02: curtin in-target -- sh -c '/bin/echo :msg, contains, \"warning:\ No such role, \" \~ >> /etc/rsyslog.d/16-mongohush.conf'
  mongo_03: curtin in-target -- sh -c '/bin/echo :msg, contains, \"command juju.\$cmd command:\" \~ >> /etc/rsyslog.d/16-mongohush.conf'
  mongo_04: curtin in-target -- sh -c '/bin/echo :msg, contains, \"command presence.\$cmd command:\" \~ >> /etc/rsyslog.d/16-mongohush.conf'

Sorry about this. I do believe it's addressed by our move to Mongo 3.2,
but I haven't tested that as the branch hasn't quite landed. It is
targeted to Juju 2.0 and Ubuntu 16.04 though.

Mark

According to our latest CI runs against Xenial with Juju 2 and Mongo 3.2, logs are no longer spammed with these messages.

\o/ thank you all :)