Comment 1 for bug 1590605

Revision history for this message
Ursula Junque (ursinha) wrote :

I have a container with 2GB of RAM and hit this issue, with juju2-beta8, while deploying landscape-dense-maas. I left it running for a while and it was enough to hit this bug.
Symptom is out of a sudden juju debug-log stops working, with no errors:

$ juju debug-log -m maastwo:controller
$ echo $?
0
$ juju debug-log -m maastwo:controller --debug
2016-06-10 22:09:55 INFO juju.cmd supercommand.go:60 running juju [2.0-beta8 gc go1.6.1]
2016-06-10 22:09:55 INFO juju.juju api.go:212 connecting to API addresses: [192.168.200.2:17070]
2016-06-10 22:09:55 INFO juju.api apiclient.go:494 dialing "wss://192.168.200.2:17070/model/13b58f00-4c31-4eaa-8dff-4d1250c040f4/api"
2016-06-10 22:09:55 INFO juju.api apiclient.go:271 connection established to "wss://192.168.200.2:17070/model/13b58f00-4c31-4eaa-8dff-4d1250c040f4/api"
2016-06-10 22:09:55 DEBUG juju.juju api.go:361 API hostnames unchanged - not resolving
2016-06-10 22:09:57 DEBUG juju.api apiclient.go:520 health ping failed: connection is shut down
2016-06-10 22:09:57 INFO cmd supercommand.go:454 command finished
$

I've logged into the machine and checked /var/log/juju/machine-0.log, here's the excerpt when executing debug-log:
2016-06-10 22:13:09 INFO juju.apiserver apiserver.go:311 [2E] API connection from 192.168.200.1:37352, active connections: 13
2016-06-10 22:13:09 DEBUG juju.apiserver utils.go:61 validate model uuid: controller model - 13b58f00-4c31-4eaa-8dff-4d1250c040f4
2016-06-10 22:13:09 DEBUG juju.apiserver apiserver.go:291 <- [2E] <unknown> {"RequestId":1,"Type":"Admin","Version":3,"Request":"Login","Params":"'params redacted'"}
2016-06-10 22:13:09 DEBUG juju.apiserver admin.go:170 hostPorts: [[192.168.200.2:17070 127.0.0.1:17070 [::1]:17070]]
2016-06-10 22:13:09 DEBUG juju.apiserver apiserver.go:305 -> [2E] user-admin@local 33.688574ms {"RequestId":1,"Response":"'body redacted'"} Admin[""].Login
2016-06-10 22:13:09 DEBUG juju.apiserver apiserver.go:291 <- [2E] user-admin@local {"RequestId":2,"Type":"Client","Version":1,"Request":"AgentVersion","Params":"'params redacted'"}
2016-06-10 22:13:09 DEBUG juju.apiserver apiserver.go:305 -> [2E] user-admin@local 584.081µs {"RequestId":2,"Response":"'body redacted'"} Client[""].AgentVersion
2016-06-10 22:13:09 INFO juju.apiserver debuglog.go:76 debug log handler starting
2016-06-10 22:13:09 DEBUG juju.apiserver utils.go:61 validate model uuid: controller model - 13b58f00-4c31-4eaa-8dff-4d1250c040f4
2016-06-10 22:13:11 ERROR juju.apiserver debuglog.go:95 debug-log handler error: tailer stopped: Executor error: OperationFailed: Sort operation used more than the maximum 33554432 bytes of RAM. Add an index, or specify a smaller limit.
2016-06-10 22:13:11 INFO juju.apiserver apiserver.go:316 [2E] user-admin@local API connection terminated after 1.750783377s, active connections: 12

Problem appears to be mongodb has an enforced 32MB limit for in-memory searches. Logs at this point are ~70MB. From my (short) investigation I gathered this is solved by using indexes, so likely a code change, not a config one.

Workaround is to log into the machine and "tail -f /var/log/juju/machine-0.log", which can be noisy if you have DEBUG on but still does the trick.