Monitoring

Monitoring is a process that detects, diagnoses, remedies and reports an application's performance and availability to ensure that it meets user expectations. Magnolia provides built-in tools for logging and debugging application behavior. It also supports Java Management Extensions (JMX), a Java technology for managing and monitoring. These mechanisms provide developers, administrators and especially the support team detailed context for application failures.

Log4j

Magnolia uses Apache log4j, a Java-based logging utility. It logs events in Magnolia core code as well as any modules that support logging. Log4j is configured in three places:

• log4j.xml file is permanent configuration. This XML file resides in the /<CATALINA_HOME>/webapps/<contextPath>/WEB-INF/config/default directory. Any configuration changes you make in this file persist through instance restarts. Conversely, you need to restart Magnolia for any changes to take effect. You should configure long-time, persistent logging here, such as sending an email notification to your own support team when errors occur in a critical component. In the XML file you can also choose whether you wish to log a single Java class or the whole package.
• Tools > Logging menu in AdminCentral is for transient configuration. Any changes you make here are active immediately but they are only valid until the next restart. When the instance is restarted, your changes revert back to default settings. This tool is useful for ad hoc debugging of production issues since you don't need to restart Magnolia to turn it on.
• Configuration > /server/auditLogging is for audit logging. Audit logging means tracking user activity in the system such as who signed in and what they did. Here you select the actions you want to audit such as login, create, activate and so on.

Turning on log4j's own debugging

If you are configuring log4j for the first time, add the debug=true attribute in the log4j:configuration element.

<log4j:configuration xmlns:log4j="http://jakarta.apache.org/log4j/" debug="true">

This will print out attributes and their values from the XML configuration file into the console at startup. This makes it easier to catch errors resulting from typos.

Categories

Categories (loggers in log4j terminology) define what data is logged and how much detail is provided. Think of categories as the classes and packages you want to log.

Here's an example from the default log4j.xml configuration file.

<category name="info.magnolia.cms.exchange" additivity="true">
   <priority value="INFO" />
   <appender-ref ref="log-activation" />
</category>

Elements and their attributes are:

• category
  • name defines the class or package to log. Type the fully-qualified Java class or package name here.
  • additivity sets appender additivity. If you set its value to true, output from the category is directed to any appenders referenced in the category itself and any appenders defined in its ancestors following the dot notation in the name attribute. If you set the value to false, output is directed only to appenders referenced in the category itself, not to ancestors. In the default configuration, typical ancestors are info.magnolia (following up the dot notation) and root at the bottom of the XML file. All categories inherit their settings from root.
• priority
  • value is the logging priority level such as INFO or DEBUG.
• appender-ref
  • ref is the name of an appender configuration in the same file.

Class or package

The choice between logging a single class or the whole package depends on whether the issue is limited to a single class. An action such as content activation is spread out over a few different classes. Logging only one of them may not provide enough information.

Example: Suppose you have an issue with content activation. Logging the info.magnolia.module.exchangesimple.BaseSyndicatorImpl class will tell you almost everything that happens when content is activated in the Community Edition since it is responsible for activating content to a subscriber. However, if you want to capture events from all related classes, set the category name to the package info.magnolia.module.exchangesimple.

To summarize:

• To log a specific class, use the fully-qualified class name as the category name.
• To log a whole package, use the fully-qualified package name as the category name.

Level

Magnolia uses the standard log4j levels.

Appenders

Appenders define where the output is directed. The following appenders are configured by default in log4j.xml. They write messages to the console and to various log files.

Example: The log-activation appender is used to log events related to content activation.

<appender name="sync-log-activation" class="org.apache.log4j.RollingFileAppender">
   <param name="File" value="${magnolia.logs.dir}/magnolia-activation.log" />
   <param name="MaxFileSize" value="1MB" />
   <param name="MaxBackupIndex" value="5" />
   <param name="Append" value="true" />
   <layout class="org.apache.log4j.PatternLayout">
      <param name="ConversionPattern" value="%-5p  %c %d{dd.MM.yyyy HH:mm:ss} -- %m%n" />
   </layout>
</appender>
<appender name="log-activation" class="org.apache.log4j.AsyncAppender">
   <appender-ref ref="sync-log-activation" />
</appender>

It is actually two appenders: log-activation appender uses the AsyncAppender class to queue up the messages while the referenced sync-log-activation appender does the actually writing of the messages to the magnolia-activation.log file.

All appenders that write to a log file use the RollingFileAppender class. Rolling means that the system takes a backup of the log file when its size reaches a limit set in the MaxFileSize parameter, 1 MB by default. The old file is date-stamped and a new file is started in the same directory.

Example: Debugging content activation

This example shows how to log more detail about content activation action. It is useful when activation fails and the default INFO messages do not provide enough information to pinpoint the root cause.

Content activation is spread out into three different packages:

• info.magnolia.cms.exchange provides some basic support objects for activation.
• info.magnolia.module.activation package is the Community Edition simple activation feature.
• info.magnolia.module.exchangetransactional is the Enterprise Edition transactional activation feature.

Add the categories to Log4j.xml if not already there:

<category name="info.magnolia.cms.exchange" additivity="true">
   <priority value="INFO" />
   <appender-ref ref="log-activation" />
</category>
<category name="info.magnolia.module.activation" additivity="true">
   <priority value="INFO" />
   <appender-ref ref="log-activation" />
</category>
<category name="info.magnolia.module.exchangetransactional" additivity="true">
   <priority value="INFO" />
   <appender-ref ref="log-activation" />
</category>

Each category references the log-activation appender which sends output to the magnolia-activation.log file. Since additivity is true, output is also sent to ancestor appenders, in this case the console.

Priority is set at INFO level by default. If more information is needed, this is the detail that needs to be changed.

To change the level to DEBUG:

1. Stop the Magnolia instance.
2. Change priority in the three categories to DEBUG.
3. Save the file.
4. Start Magnolia.

To test the new configuration, activate some content and view the logged DEBUG messages in the magnolia-activation.log.

Logging tool - transient configuration

The Logging Tool allows you to configure logging for all key Magnolia classes, as well as Apache, Ehcache and Jackrabbit classes. This configuration is transient: it only persists until the next instance restart.

 This tool does not have its own app in Magnolia 5 yet. You can access it at http://<domain>[:<port>]/<contextPath>/.magnolia/log4j.

Configuring

If you know or suspect that a particular class, group of classes or module is causing your issue, change the logging level on that class to DEBUG.

1. Go to Tools > Logging
2. Find the class in the list.
3. Select DEBUG from the drop-down list.
4. Click Set.
5. Reproduce the error.

Viewing

View the recorded messages in the log file:

1. Go to Tools > Log Viewer
2. Select magnolia-debug.log from the dropdown.
3. Click View.

Newest entries are at the end of the file. Click >> to go to the end. When the detail level is set to DEBUG, a line starting with the word DEBUG is written each time the class is called.

Downloading

To download the log file:

1. Go to Tools > Log Viewer
2. Select magnolia-debug.log from the dropdown.
3. Click Download.
4. Edit the file to include only the relevant lines where the error occurs.

Example: Logging mail errors

Mail module documentation has an example of error resolution using the logging tool.

Capturing request and response headers

Request and response headers are information passed between a browser and a web server. Headers consist of fields that define the operating parameters of the HTTP transaction. Capturing the headers tells you what records are passed and provides a clue for troubleshooting.

The request header contains details of what the browser wants and what it will accept back from the server. It also contains the type, version and capabilities of the browser so that the server returns compatible data.

Example: Request header

User-Agent: Mozilla/5.0 (Macintosh; Intel Mac OS X 10_6_8) AppleWebKit/534.50 (KHTML, like Gecko) Version/5.1 Safari/534.50
Accept: text/html,application/xhtml+xml,application/xml;q=0.9,*/*;q=0.8
Referer: http://demopublic.magnolia-cms.com/demo-project.html
Cache-Control: max-age=0

The response header contains the date, size and type of file that the server is sending back to the client and data about the server itself. The header is attached to the files being sent back to the client.

Example: Response header

Date: Thu, 13 Oct 2011 11:09:41 GMT
Content-Encoding: gzip
Connection: Keep-Alive
Content-Length: 3229
Pragma: no-cache
X-Magnolia-Registration: Registered
Last-Modified: Thu, 13 Oct 2011 11:01:26 GMT
Server: Apache/2.2.14 (Ubuntu)
Vary: Accept-Encoding
Content-Type: text/html;charset=UTF-8
Cache-Control: no-cache, no-store, must-revalidate, max-age=0
Keep-Alive: timeout=15, max=100
Expires: Thu, 01 Jan 1970 00:00:00 GMT

Browser extensions

To capture the headers, you can use a browser extension or plugin that displays headers for the currently open page. A plugin's advantage over a header-sniffing website is that you can also use it for sites that only exist in your local environment or intranet.

• Safari: Developer Tools
• Firefox: Web Developer or Live HTTP Headers add-on
• Chrome: Developer Tools
• Internet Explorer: Fiddler

To view headers in Developer Tools:

1. Open Developer Tools.
2. Go to Network.
3. Reload the page.
4. Select the page in the list.
5. Go to Headers tab.

Command line tools

Any Unix-like system likely has these command line tools already installed.

• cURL
  $ curl --head <url>
• wget
  $ wget --server-response <url>

Applications

Rich client applications:

• Wireshark. See Capturing HTTP traffic.

Websites

A header-sniffing website can report headers for a site that resides on the public Internet. These tools do not work for a site that exists only in your local environment.

• Web-Sniffer
• Rex Swain's HTTP Viewer

JMX monitoring

You can observe Java Virtual Machine and application server performance through Java Management Extensions (JMX). JMX is Java technology used for managing and monitoring applications and system objects. Objects are represented as management beans (MBean). JMX is supported by many Java application servers such as Apache Tomcat, JBoss AS, IBM WebSphere and Oracle WebLogic.

JConsole

Java Monitoring and Management Console (JConsole) is a graphical tool that supports JMX monitoring and management on a local or remote machine. It draws graphs for visual representation of performance and resource consumption, which makes it easier to observe changes over time. As a downside, the results are not as easy to export as with Jmxterm.

Starting JConsole

1. Start JConsole: $ jconsole
2. Connect to a process:
   • Local: Select a Java process running on the local machine. Magnolia running on Tomcat would be listed as org.apache.catalina.startup.Boostrap start.
   • Remote: Type a remote process location as <hostname>:<port> or service:jmx:<protocol>:<sap>.
3. Click Connect

See Using JConsole for instructions on how to view and interpret the charts.

Saving Chart Data

To save data from a JConsole chart in CSV format:

1. Right-click the chart and select Save data as...
2. Specify a file to save.

The CSV file can be imported into a spreadsheet to re-create the chart.

Example: Flushing the cache in JConsole

JMX is not only used to observe events. You can also invoke operations. In this example the server cache is flushed on the public instance using JConsole:

1. Open JConsole and connect to the Magnolia process.
2. Go to the MBeans tab.
3. Expand Magnolia > Cachemonitor > magnoliaPublic > Operations. This is a list of invokable operations provided by the CacheMonitor MBean.
4. Click flushAll to invoke the flush operation.

Jmxterm

Jmxterm is a command line JMX tool. Unlike JConsole, it does not have a graphical user interface. However, its big advantage is that Magnolia Support can give you a script that you can paste into your Jmxterm and run it. You can also write the Jmxterm output to a file and attach it to a support ticket. This makes it easier to collect and analyze specific data. Jmxterm is good for point-in-time observation whereas JConsole is better for visualizing events over a longer period.

Example: Flushing the cache in Jmxterm

Start Jmxterm.

$ java -jar jmxterm.jar 
Welcome to JMX terminal. Type "help" for available commands.

The jvms command tells you what Java processes are running on the machine.

$>jvms
5622     ( ) - jmxterm.jar
4623     ( ) - sun.tools.jconsole.JConsole
2094     (m) - org.apache.catalina.startup.Bootstrap start

Open the connection to the Catalina JVM using the process ID.

$>open 2094
#Connection to 2094 is opened

The domains command lists the domains available in the Java process.

$>domains
#following domains are available
Catalina
JMImplementation
Magnolia
Users
com.sun.management
java.lang
java.util.logging
net.sf.ehcache

Set the domain to Magnolia.

$>domain Magnolia
#domain is set to Magnolia

The beans command provides a list of MBeans in the domain. Here are the beans in the Magnolia domain.

$>beans
#domain = Magnolia:
Magnolia:domain=magnoliaAuthor,type=CacheMonitor
Magnolia:domain=magnoliaAuthor,type=JCRStats
Magnolia:domain=magnoliaPublic,type=CacheMonitor
Magnolia:domain=magnoliaPublic,type=JCRStats

We need the CacheMonitor bean for the public instance.

$>bean Magnolia:domain=magnoliaPublic,type=CacheMonitor
#bean is set to Magnolia:domain=magnoliaPublic,type=CacheMonitor

info tells you what a bean does. The CacheMonitor bean provides several attributes and operations.

$>info
#mbean = Magnolia:domain=magnoliaPublic,type=CacheMonitor
#class name = info.magnolia.module.cache.mbean.CacheMonitor
# attributes
  %0   - All (java.util.Map, r)
  %1   - Bypasses (int, r)
  %2   - CachedKeysCount (int, r)
  %3   - CachedUUIDsCount (int, r)
  %4   - DomainAccesses (java.util.Map, r)
  %5   - Flushes (java.util.Map, r)
  %6   - Hits (int, r)
  %7   - Puts (int, r)
  %8   - StartCalls (int, r)
  %9   - StopCalls (int, r)
# operations
  %0   - void flushAll()
  %1   - void flushByUUID(java.lang.String p1,java.lang.String p2)
#there's no notifications

Invoke the flushAll operation to flush the cache.

$>run flushAll
#calling operation flushAll of mbean Magnolia:domain=magnoliaPublic,type=CacheMonitor
#operation returns: 
null

This particular operation does not return any value, just null.

Let's see how many times the cache has been flushed by checking the Flushes attribute with the get command.

$>get Flushes 
#mbean = Magnolia:domain=magnoliaPublic,type=CacheMonitor:
Flushes = { 
  uuid-key-mapping = 3;
  default = 3;
 };

Three times, it seems.

Example: Running a Jmxterm script

Jmxterm can read a script file with the -i <input script> command line option.

Save the following script as script.txt:

open <JVM process ID>
get -d Magnolia -b Magnolia:domain=magnoliaPublic,type=JCRStats SessionCount
get -d Magnolia -b Magnolia:domain=magnoliaPublic,type=CacheMonitor All
quit

Replace <JVM process ID> with the ID of the Java Virtual Machine that is executing the Magnolia application. You can find it with ps | grep jvm.

Execute the script with:

$ java -jar jmxterm.jar -n -i script.txt -o output.txt

where

• -n sets Jmxterm to non-interactive mode.
• -i <input script> reads the script.
• -o <output file> writes the output to a file.

You should get results like this in the output file:

SessionCount = 12;
CachedUUIDsCount = 7;