Bug #70523 logging of the MEM agent is very verbose and does not give functional info
Submitted: 4 Oct 2013 14:30 Modified: 9 Jan 2015 10:15
Reporter: Simon Mudd (OCA) Email Updates:
Status: Closed Impact on me:
None 
Category:MySQL Enterprise Monitor: Agent Severity:S3 (Non-critical)
Version:3.0.2.2900 OS:Any
Assigned to: CPU Architecture:Any
Tags: windmill

[4 Oct 2013 14:30] Simon Mudd
Description:
The MEM agent provides log files with a lot of information, which includes java tracebacks of the functions called etc. This is just noise and hides the "real messages" of things that a user want to see, like:

- did the agent connect to the mem dashboard , and where is it?
- did the agent connect to the MySQL server, and where is it
- ....

There's no need in production software, under normal circumstances to provide the logging in the style that this is done. The logging should IMO provide functional messages about what the agent is doing and of course include information on issues and their recovery etc, but that should be written in a non "java" way.

This would save a lot of space, and while this information may be of interest to the developers in normal day to day operations it is just noise.

If we need the info I am sure support will tell us how to adjust the logging to provide a more verbose output.

How to repeat:
install an agent and look at the log file:

Example useless message (in the format that's currently used):

2013-10-04 16:08:36,149 ERROR [cme.schedule.Scheduler-3:com.mysql.etools.agent.collection.impl.InventoryConcentrator] com.mysql.etools.limits.OpenCircuitException: The circuit breaker ClosedStateUtilizeImpl-com.mysql.etools.agent.collection.MysqlConnection@e5364 has been opened, normal execution will resume at 2013-10-04T14:08:36.160Z
com.mysql.etools.limits.OpenCircuitException: The circuit breaker ClosedStateUtilizeImpl-com.mysql.etools.agent.collection.MysqlConnection@e5364 has been opened, normal execution will resume at 2013-10-04T14:08:36.160Z
        at com.mysql.etools.limits.CircuitBreakerTemplate$OpenCircuitBreakerState.preExecute(CircuitBreakerTemplate.java:151)
        at com.mysql.etools.limits.CircuitBreakerTemplate.execute(CircuitBreakerTemplate.java:230)
        at com.mysql.etools.agent.collection.MysqlConnection$ClosedState.utilizeImpl(MysqlConnection.java:569)
        at com.mysql.etools.agent.collection.MysqlConnection$ClosedState.utilize(MysqlConnection.java:581)
        at com.mysql.etools.agent.collection.MysqlConnection.utilizeCall(MysqlConnection.java:916)
        at com.mysql.etools.agent.collection.MysqlConnection.access$3100(MysqlConnection.java:62)
        at com.mysql.etools.agent.collection.MysqlConnection$5.execute(MysqlConnection.java:948)
        at com.mysql.etools.agent.collection.PrivilegeFallback.attempt(PrivilegeFallback.java:19)
        at com.mysql.etools.agent.collection.MysqlConnection.utilize(MysqlConnection.java:952)
        at com.mysql.etools.agent.collection.support.QueryResultsProvider.getResults(QueryResultsProvider.java:51)
        at com.mysql.etools.agent.collection.mysql.CachedResultsProvider$1.get(CachedResultsProvider.java:41)
        at com.mysql.etools.agent.collection.mysql.CachedResultsProvider$1.get(CachedResultsProvider.java:36)
        at com.google.common.base.Suppliers$ExpiringMemoizingSupplier.get(Suppliers.java:192)
        at com.mysql.etools.agent.collection.mysql.CachedResultsProvider.getResults(CachedResultsProvider.java:52)
        at com.mysql.etools.agent.collection.mysql.AssetsResultsInventoryProvider.fetchFrom(AssetsResultsInventoryProvider.java:246)
        at com.mysql.etools.agent.collection.mysql.AssetsResultsInventoryProvider.fetchRequiredSnapshots(AssetsResultsInventoryProvider.java:231)
        at com.mysql.etools.agent.collection.mysql.AssetsResultsInventoryProvider.fetch(AssetsResultsInventoryProvider.java:112)
        at com.mysql.etools.agent.collection.impl.InventoryConcentrator$ProvidersIterator.computeNext(InventoryConcentrator.java:119)
        at com.mysql.etools.agent.collection.impl.InventoryConcentrator$ProvidersIterator.computeNext(InventoryConcentrator.java:95)
        at com.google.common.collect.AbstractIterator.tryToComputeNext(AbstractIterator.java:143)
        at com.google.common.collect.AbstractIterator.hasNext(AbstractIterator.java:138)
        at com.google.common.collect.ImmutableList.copyOf(ImmutableList.java:263)
        at com.google.common.collect.ImmutableList.copyOf(ImmutableList.java:223)
        at com.mysql.etools.agent.collection.impl.MetricCollectionConcentrator.doCollect(MetricCollectionConcentrator.java:73)
        at com.mysql.etools.agent.collection.impl.MetricCollectionConcentrator.collect(MetricCollectionConcentrator.java:64)
        at com.mysql.etools.agent.collection.impl.AgentShim.collect(AgentShim.java:22)
        at com.mysql.etools.agent.order.InventoryCollectionOrder.run(InventoryCollectionOrder.java:95)
        at com.mysql.etools.agent.order.InventoryCollectionOrder.access$000(InventoryCollectionOrder.java:26)
        at com.mysql.etools.agent.order.InventoryCollectionOrder$1.run(InventoryCollectionOrder.java:75)
        at org.springframework.scheduling.support.DelegatingErrorHandlingRunnable.run(DelegatingErrorHandlingRunnable.java:51)
        at org.springframework.scheduling.concurrent.ReschedulingRunnable.run(ReschedulingRunnable.java:81)
        at java.util.concurrent.Executors$RunnableAdapter.call(Unknown Source)
        at java.util.concurrent.FutureTask$Sync.innerRun(Unknown Source)
        at java.util.concurrent.FutureTask.run(Unknown Source)
        at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$201(Unknown Source)
        at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(Unknown Source)
        at java.util.concurrent.ThreadPoolExecutor.runWorker(Unknown Source)
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(Unknown Source)
        at java.lang.Thread.run(Unknown Source)

The functional details here are about some circuit breaker thing, but the rest is just noise really.
Even then trying to understand what it's talking about is not easy.

Suggested fix:
reduce logging to provide functional information, but don't remove information that does need to be recorded. the java tracebacks are really not helpful for non developers.

Change the language of the messages to be functional. That's clearer.
[18 Jul 2014 9:40] Sean Scullion
Totally agree with Simon. I'm getting hundreds of lines of irrelevant output per minute and it would be great if this was configurable...
[18 Jul 2014 14:22] Mark Matthews
It is configurable, see $agent_home/etc/log4j.properties. Change levels on any category to whatever you need, where categories are the strings after the : inside the [], the left is the thread name.

2013-10-04 16:08:36,149 ERROR
[cme.schedule.Scheduler-3:com.mysql.etools.agent.collection.impl.InventoryConcentrator]

com.mysql.etools.agent.collection.impl.InventoryConcentrator is the category, add/adjust a line similar to this in log4j.properties

log4j.logger.com.mysql.etools.agent.collection.impl.InventoryConcentrator = [OFF
, FATAL, ERROR, WARN, INFO, DEBUG,TRACE]

You can also apply a level to a "class" of categories, by using some portion of the package name, i.e the following would set all logging for anything doing collection at the agent to the FATAL level:

log4j.logger.com.mysql.etools.agent.collection = FATAL
 
Note that some time ago we split the log in two, one with stack traces, one only with messages (...-full.log). While the logs seem verbose, they have helped us solve many customer issues without us having to ask them to re-crash the car. If they are too noisy for you, they are customizable as show above, but you may be asked to re-enable verbosity and reproduce situations for support issue handling.