Did you ever want to find out if your MoM, a collector or an agent is healthy? What did you do? Look at sustainability metrics in the Workstation/WebView or look at log files?
I guess that 80% looked at log files - and had no clue what to look for and what this all means:
6/19/15 04:58:00.632 PM PDT [INFO] [main] [Manager.Agent] Setting cache size to hold 32 elements
6/19/15 04:58:00.632 PM PDT [INFO] [main] [Manager.Agent] Agent automatic unmount delay configured to 60 minute(s).
6/19/15 04:58:00.669 PM PDT [WARN] [main] [Manager.Agent] An error occurred while loading metric shutoff configuration from /Applications/Introscope9.7.1.16/config/shutoff/MetricShutoffConfiguration.xml.
6/19/15 04:58:04.427 PM PDT [INFO] [main] [Manager.TransactionTracer] Storage directory configured to /Applications/Introscope9.7.1.16/traces
6/19/15 04:58:04.427 PM PDT [INFO] [main] [Manager.TransactionTracer] Configured introscope.enterprisemanager.transactionevents.storage.queue.limit to 1000
6/19/15 04:58:04.818 PM PDT [INFO] [main] [Manager.TransactionTracer] First Live Perst Storage Rollover will be run at Sat Jun 20 00:00:00 PDT 2015
6/19/15 04:58:04.819 PM PDT [INFO] [main] [Manager] Optimization frequency configured to 24 hours
6/19/15 04:58:04.819 PM PDT [INFO] [PO Async Executor] [Manager.TransactionTracer] Configured Lucene max allowed segments to 3 segments.
6/19/15 04:58:04.820 PM PDT [INFO] [main] [Manager] Optimization time offset configured to 2:00
6/19/15 04:58:04.820 PM PDT [INFO] [main] [Manager] Data age configured to 14 days
6/19/15 04:58:04.820 PM PDT [INFO] [main] [Manager] First scheduled optimization will be run at Sat Jun 20 02:00:00 PDT 2015
6/19/15 04:58:04.822 PM PDT [INFO] [Event Pump Entity] [Manager.TransactionTracer] Enabling ErrorDetector...
6/19/15 04:58:04.822 PM PDT [INFO] [Event Pump Entity] [Manager.TransactionTracer] ErrorDetector started
6/19/15 04:58:04.881 PM PDT [INFO] [main] [Manager.Database] Database queue limited to 153600 data points.
6/19/15 04:58:04.886 PM PDT [INFO] [main] [Manager.Database] Using default value for introscope.enterprisemanager.db.numberOfReconnectionAttempts: 0
6/19/15 04:58:04.889 PM PDT [INFO] [main] [Manager.FlatFile] Flat files will be written to /Applications/Introscope9.7.1.16/flatfiles
6/19/15 04:58:04.889 PM PDT [INFO] [main] [Manager.FlatFile] Archiving flat files based on time is disabled
6/19/15 04:58:04.890 PM PDT [INFO] [main] [Manager.FlatFile] Flat files will be archived when they are larger than 100M
6/19/15 04:58:04.890 PM PDT [INFO] [main] [Manager.FlatFile] Flat files will be closed after 10 consecutive errors.
6/19/15 04:58:04.890 PM PDT [INFO] [main] [Manager.FlatFile] The maximum number of concurrent flat file archiver threads will be 5.
6/19/15 04:58:04.891 PM PDT [INFO] [main] [Manager.FlatFile] Flat file compression is enabled
6/19/15 04:58:04.919 PM PDT [INFO] [main] [Manager.Action] At most 5 actions will be triggered at any one time
6/19/15 04:58:04.988 PM PDT [INFO] [PO Async Executor] [Manager] Heuristics enabled for agents matching expression: ".*"
6/19/15 04:58:04.991 PM PDT [INFO] [main] [Manager.JavaScriptCalculator] Scripts directory configured to /Applications/Introscope9.7.1.16/./scripts
6/19/15 04:58:04.991 PM PDT [INFO] [main] [Manager.JavaScriptCalculator] Using default value for introscope.enterprisemanager.javascript.refresh: 60
6/19/15 04:58:04.991 PM PDT [INFO] [main] [Manager.JavaScriptCalculator] Value of introscope.enterprisemanager.javascript.refresh is 60 seconds
6/19/15 04:58:04.992 PM PDT [INFO] [main] [Manager.JavaScriptCalculator] Deploying JavaScript calculator /Applications/Introscope9.7.1.16/./scripts/BtStats-AggregatedTree.java
Wouldn't it be nice if you could just organize your APM log files into smaller chunks? Have just one log file for ERRORs and WARNINGs? Have another one for everything CEM related - which many customers still don't have?
Well, that's easy as I'm going to show you in this blog!
All (well most) APM log files are based on a log4j configuration. That means you can assign different files (appenders) and different log levels to different loggers. A logger is basically just a name but most often the name of the java package that the class that is logging belongs to. There are a lot of different loggers used in CA APM and some of them are visible if you look at the log4j configuration in IntroscopeEnterpriseManager.properties for an EM and IntroscopeAgent.profile for an agent.
So for this blog we have 3 goals (and a bonus):
- We want to create a log file that only contains ERRORs and WARNINGs.
- We want to move all logging for CEM into a separate log file.
- We don't want any logging to go to the console (stdout, stderr).
Error logging
First we define a new appender in IntroscopeEnterpriseManager.log:
log4j.appender.error.File=logs/error.log
Next we configure this appender:
To configure our error appender we just copy everything from another appender (e.g. logfile) and replace the appender name logfile with error:
log4j.appender.error=com.wily.org.apache.log4j.RollingFileAppender
log4j.appender.error.layout=com.wily.org.apache.log4j.PatternLayout
log4j.appender.error.layout.ConversionPattern=%d{M/dd/yy hh:mm:ss.SSS a z} [%-3p] [%t] [%c] %m%n
log4j.appender.error.MaxBackupIndex=4
We don't assume that we will have lots of errors and therefore set the file size to 2MB:
log4j.appender.error.MaxFileSize=2MB
Finally we want only messages with a log level of WARN or ERROR to be written to this file (sent to this appender). Therefore we set a threshold of WARN:
log4j.appender.error.Threshold=WARN
Now we only need to add our appender to all the loggers defined in the IntroscopeEnterpriseManager.properties:
log4j.logger.Manager=INFO, logfile, error
log4j.logger.com.wily=INFO, logfile, error
log4j.logger.com.timestock=INFO, logfile, error
[and so on]
Notice that the log level for most of these loggers is still set to INFO. So INFO level messages are sent to both loggers but only written to logfile (which is our IntroscopeEnterpriseManager.log) but not to our error.log because the threshold suppresses everything below level WARN.
Also note that log4j configuration works on the fly without a restart! So a new file error.log should be creating within a minute of saving your configuration file.
CEM logging
Loggers and appenders
If you take a look at your log file you can see the loggers:
log4j.logger.Manager=INFO, console, logfile
log4j.logger.Manager.Support=INFO, supportlogfile
log4j.logger.com.wily=INFO, console, logfile
log4j.logger.com.timestock=INFO, console, logfile
log4j.logger.Manager.com.timestock=INFO, console, logfile
log4j.logger.Manager.com.wily.apm.tess=INFO, console, logfile
log4j.logger.com.ca.wily=INFO, console, logfile
log4j.logger.Apm.Data.Model=INFO, console, logfile
log4j.logger.apm.events=INFO, console, logfile
And the appenders:
# If logfile is specified above, the location of the log file
# is configured with the following property,
# log4j.appender.logfile.File. Full paths can
# be used if desired.
log4j.appender.logfile.File=logs/IntroscopeEnterpriseManager.log
log4j.appender.supportlogfile.File=logs/IntroscopeEnterpriseManagerSupport.log
log4j.appender.error.File=logs/Error.log
########## See Warning below ##########
# Warning: The following properties should not be modified for normal use.
log4j.additivity.Manager=false
log4j.appender.console=com.wily.org.apache.log4j.ConsoleAppender
log4j.appender.console.layout=com.wily.org.apache.log4j.PatternLayout
log4j.appender.console.layout.ConversionPattern=%d{M/dd/yy hh:mm:ss.SSS a z} [%-3p] [%t] [%c] %m%n
log4j.appender.logfile=com.wily.org.apache.log4j.RollingFileAppender
log4j.appender.logfile.layout=com.wily.org.apache.log4j.PatternLayout
log4j.appender.logfile.layout.ConversionPattern=%d{M/dd/yy hh:mm:ss.SSS a z} [%-3p] [%t] [%c] %m%n
log4j.appender.logfile.MaxBackupIndex=4
log4j.appender.logfile.MaxFileSize=200MB
log4j.appender.supportlogfile=com.wily.org.apache.log4j.RollingFileAppender
log4j.appender.supportlogfile.layout=com.wily.org.apache.log4j.PatternLayout
log4j.appender.supportlogfile.layout.ConversionPattern=%d{M/dd/yy hh:mm:ss a z} [%-3p] [%c] %m%n
log4j.appender.supportlogfile.MaxBackupIndex=4
log4j.appender.supportlogfile.MaxFileSize=20MB
Conversion Pattern
The conversion pattern tells log4j how to format the output. The pattern "%d{M/dd/yy hh:mm:ss.SSS a z} [%-3p] [%t] [%c] %m%n" result in log messages formatted like this:
6/19/15 04:57:58.783 PM PDT [INFO] [main] [Manager] Introscope Enterprise Manager Release 9.7.1.16 (Build 16)
6/19/15 04:57:58.788 PM PDT [INFO] [main] [Manager] Using Java VM version "Java HotSpot(TM) 64-Bit Server VM 1.7.0_67" from Oracle Corporation
6/19/15 04:57:58.788 PM PDT [INFO] [main] [Manager] Using Introscope installation at: /Applications/Introscope9.7.1.16/.
6/19/15 04:57:58.788 PM PDT [INFO] [main] [Manager] CA Wily Introscope(R) Version 9.7.1
6/19/15 04:57:58.788 PM PDT [INFO] [main] [Manager] Copyright (c) 2015 CA. All Rights Reserved.
6/19/15 04:57:58.788 PM PDT [INFO] [main] [Manager] Introscope(R) is a registered trademark of CA.
6/19/15 04:57:58.788 PM PDT [INFO] [main] [Manager] Starting Introscope Enterprise Manager...
6/19/15 04:57:59.259 PM PDT [INFO] [main] [Manager.HotFailover] Hot Failover not enabled
6/19/15 04:57:59.268 PM PDT [INFO] [main] [Manager] The Introscope Enterprise Manager is set to run in StandAlone mode.
6/19/15 04:57:59.286 PM PDT [INFO] [main] [Manager] Starting server...
6/19/15 04:57:59.681 PM PDT [INFO] [main] [Manager.Authentication] Introscope WebView connections are enabled
6/19/15 04:57:59.681 PM PDT [INFO] [main] [Manager.Authentication] Introscope WebView connections will be assigned the name "WilyWebView"
6/19/15 04:57:59.777 PM PDT [INFO] [main] [Manager.Authentication] Configured the Manager of Managers user using private key internal/server/EM.private
The first part is obviously date, time and timezone, the next parts are the log level (%-3p), the thread (%t), the logger (category - %c) and finally the message (%m) and a newline (%n). So from the log file you can directly see which logger is logging the message: Manager and Manager.Authentication in the above example. We'll get back to that in a minute.
Logger definition
Again we need to define our CEM log appender first:
log4j.appender.cemlogfile.File=logs/IntroscopeCEM.log
log4j.appender.cemlogfile=com.wily.org.apache.log4j.RollingFileAppender
log4j.appender.cemlogfile.layout=com.wily.org.apache.log4j.PatternLayout
log4j.appender.cemlogfile.layout.ConversionPattern=%d{M/dd/yy hh:mm:ss.SSS a z} [%-3p] [%t] [%c] %m%n
log4j.appender.cemlogfile.MaxBackupIndex=4
log4j.appender.cemlogfile.MaxFileSize=200MB
Next we look at the IntroscopeEnterpriseManager.log and identify all the loggers used for CEM logging. For those loggers we replace the default logfile with cemlogfile:
log4j.logger.com.timestock=INFO, cemlogfile, error
log4j.logger.Manager.com.timestock=INFO, cemlogfile, error
log4j.logger.Manager.com.wily.apm.tess=INFO, cemlogfile, error
log4j.additivity.com.timestock=false
log4j.additivity.Manager.com.timestock=false
log4j.additivity.Manager.com.wily.apm.tess=false
We leave all of them at the INFO log level and instruct log4j to log messages from those loggers to both them cemlogfile and the error log file.
For those that wonder what timestock and tess mean: that is the company that invented CEM, got bought by Wily Technologies which in turn was acquired by CA Technologies. The CEM server used to be a standalone server from the Enterprise Manager called TESS (Transaction, Events and Statistics Server) and was later integrated into the EM.
If you want to get rid of all the "table/partition created/dropped" message you can add:
log4j.logger.
Manager.com.timestock.tess.util.DbUtils=WARN, cemlogfile, error
log4j.additivity
.
Manager.com.timestock.tess.util.DbUtils=false
Removing console logging
So now for the last part. That is really the easiest of the three steps: just search your IntroscopeEnterpriseManager.log for all references to console and remove them or replace them with logfile, cemlogfile or error.
The same can be applied to most other APM log files like IntroscopeAgent.log and EPAgent.log. E.g. when I'm testing new field packs or configurations I use something like the following snippet. By commenting out two of the first three lines I can quickly switch between different log levels. Using the threshold I can defined that DEBUG messages only go to my debug.log.
#log4j.logger.EPAgent=INFO, logfile
#log4j.logger.EPAgent=VERBOSE#com.wily.util.feedback.Log4JSeverityLevel, logfile
log4j.logger.EPAgent=DEBUG, logfile, debuglogfile
log4j.appender.logfile.File=EPAgent.log
log4j.appender.logfile.Threshold=INFO
#log4j.appender.logfile.Threshold=VERBOSE#com.wily.util.feedback.Log4JSeverityLevel
log4j.appender.debuglogfile.File=debug.log
The log levels used by CA APM are:
TRACE,
DEBUG,
VERBOSE#com.wily.util.feedback.L4JSeverityLevel,
INFO,
WARN,
ERROR,
FATAL
An example logging configuration for an Enterprise Manager based on the above is attached.
For more information see Apache log4j 1.2 - Short introduction to log4j.