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

Bug #1349949 reported by Mark Shuttleworth on 2014-07-29
98
This bug affects 20 people
Affects Status Importance Assigned to Milestone
juju
High
Unassigned
juju-core
High
Unassigned
1.25
High
Unassigned
mongodb (Ubuntu)
Undecided
Unassigned

Bug Description

Watching cloud installs I've noticed that 95% of my syslog becomes mongo db debugging output. It seems unnecessary to have that be the default behaviour. If it's something Landscape asked for, let's move the bug there and fix it, if it's something Juju is doing by default can we drop the logging level to a more reasonable notch? Errors would be useful, but millions of lines like:

Jul 29 16:31:51 maas-1-04 mongod.37017[360]: Tue Jul 29 16:31:51.525 [initandlisten] connection accepted from 127.0.0.1:53049 #24 (18 connections now open)
Jul 29 16:31:51 maas-1-04 mongod.37017[360]: Tue Jul 29 16:31:51.527 [conn13] authenticate db: juju { authenticate: 1, nonce: "74375d847596cd1c", user: "machine-0", key: "e9f35c473f3b73b57b48e32d5eaecc50" }
Jul 29 16:31:51 maas-1-04 mongod.37017[360]: Tue Jul 29 16:31:51.527 [conn14] authenticate db: juju { authenticate: 1, nonce: "8c236ac4aeb30e01", user: "machine-0", key: "87822d1b996c6d2d2d346ebe1ca2ffb9" }
Jul 29 16:31:51 maas-1-04 mongod.37017[360]: Tue Jul 29 16:31:51.527 [conn12] authenticate db: juju { authenticate: 1, nonce: "c193443e9216a8f", user: "machine-0", key: "028540c4cb9b0baa503b0f068f6daa09" }
Jul 29 16:31:51 maas-1-04 mongod.37017[360]: Tue Jul 29 16:31:51.527 [conn13] warning: No such role, "readWriteAnyDatabase", in database juju. No privileges will be acquired from this role
Jul 29 16:31:51 maas-1-04 mongod.37017[360]: Tue Jul 29 16:31:51.527 [conn12] warning: No such role, "readWriteAnyDatabase", in database juju. No privileges will be acquired from this role

... are not:)

Mark Shuttleworth (sabdfl) wrote :

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

Curtis Hovey (sinzui) on 2014-07-29
tags: added: logging mongodb
Changed in juju-core:
status: New → Triaged
importance: Undecided → High
milestone: none → 1.21-alpha1
David Britton (dpb) on 2014-07-30
tags: added: cloud-installer landscape

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

Dean Henrichsmeyer (dean) wrote :

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

Mark Shuttleworth (sabdfl) wrote :

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

Mark

Curtis Hovey (sinzui) on 2014-09-10
Changed in juju-core:
milestone: 1.21-alpha1 → 1.21-alpha2
Curtis Hovey (sinzui) on 2014-10-23
Changed in juju-core:
milestone: 1.21-alpha2 → 1.21-alpha3
Curtis Hovey (sinzui) on 2014-11-04
Changed in juju-core:
milestone: 1.21-alpha3 → 1.21-beta1
Ian Booth (wallyworld) on 2014-11-06
Changed in juju-core:
milestone: 1.21-beta1 → 1.22
Christian Reis (kiko) wrote :

Isn't this a dupe of bug 1365828?

Changed in juju-core:
milestone: 1.22-alpha1 → 1.23
Casey Marshall (cmars) on 2015-03-05
Changed in juju-core:
assignee: nobody → Casey Marshall (cmars)
status: Triaged → In Progress
David Britton (dpb) wrote :

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! :(

Curtis Hovey (sinzui) on 2015-04-21
Changed in juju-core:
milestone: 1.23 → 1.24-alpha1
Changed in juju-core:
milestone: 1.24-alpha1 → 1.25.0
milestone: 1.25.0 → none
Casey Marshall (cmars) on 2015-05-06
Changed in juju-core:
status: In Progress → Confirmed
assignee: Casey Marshall (cmars) → nobody
Curtis Hovey (sinzui) on 2015-05-06
Changed in juju-core:
status: Confirmed → Triaged
Ian Booth (wallyworld) wrote :

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.

Ian Booth (wallyworld) on 2015-05-07
Changed in juju-core:
milestone: none → 1.25.0
Horacio Durán (hduran-8) wrote :

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

Horacio Durán (hduran-8) wrote :

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

Curtis Hovey (sinzui) wrote :

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.

no longer affects: juju-core/1.24
John A Meinel (jameinel) wrote :

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.

Jonathan Davies (jpds) wrote :

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:" ~

tags: added: canonical-bootstack
Mark Shuttleworth (sabdfl) wrote :

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.

Christian Reis (kiko) 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)?

Ian Booth (wallyworld) wrote :

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.

Curtis Hovey (sinzui) on 2015-08-27
Changed in juju-core:
milestone: 1.25-alpha1 → 1.25-beta1
Changed in juju-core:
milestone: 1.25-beta1 → 1.26-alpha1
Robie Basak (racb) wrote :

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.

Changed in mongodb (Ubuntu):
status: New → Incomplete
Jorge Niedbalski (niedbalski) wrote :
Download full text (6.9 KiB)

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...

Read more...

tags: added: sts
Mark Shuttleworth (sabdfl) wrote :

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

Mark

Curtis Hovey (sinzui) on 2015-11-03
Changed in juju-core:
milestone: 1.26-alpha1 → 1.26-alpha2
Changed in juju-core:
milestone: 1.26-alpha2 → 1.26-beta1
Changed in juju-core:
milestone: 1.26-beta1 → 2.0-alpha2
Changed in juju-core:
milestone: 2.0-alpha2 → 2.0-alpha3
Paul Gear (paulgear) wrote :

This is still affecting us on 1.25.3.

Mark Shuttleworth (sabdfl) wrote :

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

tags: added: sts-needs-review
Changed in juju-core:
milestone: 2.0-alpha3 → 2.0-beta4
Bojan Landekic (blandekic) wrote :

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

Matt Dirba (5qxm) wrote :

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'

Mark Shuttleworth (sabdfl) wrote :

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

Curtis Hovey (sinzui) on 2016-04-14
Changed in juju-core:
milestone: 2.0-beta4 → 2.0-rc1
Curtis Hovey (sinzui) on 2016-04-20
Changed in juju-core:
milestone: 2.0-beta5 → 2.0-rc1
Curtis Hovey (sinzui) on 2016-04-25
Changed in juju-core:
milestone: 2.0-beta6 → 2.0-beta7
Curtis Hovey (sinzui) on 2016-05-13
Changed in juju-core:
milestone: 2.0-beta7 → 2.0-beta8
Changed in juju-core:
milestone: 2.0-beta8 → 2.0-beta9
Curtis Hovey (sinzui) on 2016-06-16
Changed in juju-core:
milestone: 2.0-beta9 → 2.0-beta10
Curtis Hovey (sinzui) on 2016-06-24
Changed in juju-core:
milestone: 2.0-beta10 → 2.0-beta11
Curtis Hovey (sinzui) on 2016-07-01
Changed in juju-core:
milestone: 2.0-beta11 → 2.0-beta12
Changed in juju-core:
milestone: 2.0-beta12 → 2.0-beta13
Curtis Hovey (sinzui) on 2016-07-22
Changed in juju-core:
milestone: 2.0-beta13 → 2.0-beta14
Paul Gear (paulgear) on 2016-07-27
tags: added: canonical-is
Curtis Hovey (sinzui) on 2016-08-04
Changed in juju-core:
milestone: 2.0-beta14 → 2.0-beta15
Changed in juju-core:
milestone: 2.0-beta15 → 2.0.0
tags: removed: sts sts-needs-review
Changed in juju-core:
milestone: 2.0.0 → 2.0-beta16
Changed in juju-core:
milestone: 2.0-beta16 → 2.0-beta17
affects: juju-core → juju
Changed in juju:
milestone: 2.0-beta17 → none
milestone: none → 2.0-beta17
Changed in juju-core:
importance: Undecided → High
status: New → Won't Fix
Anastasia (anastasia-macmood) wrote :

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

Changed in juju:
status: Triaged → Fix Committed
milestone: 2.0-beta17 → 2.0-beta16
Curtis Hovey (sinzui) on 2016-08-25
Changed in juju:
status: Fix Committed → Fix Released
Mark Shuttleworth (sabdfl) wrote :

\o/ thank you all :)

To post a comment you must log in.
This report contains Public information  Edit
Everyone can see this information.

Duplicates of this bug

Other bug subscribers