Using Apache Chainsaw to view the MPS log

by

Like most programs, MPS writes messages to a log file — lots of messages. To make sense of so many messages, it helps to use a tool that improves the visual presentation, for example:

  • grid display: separate fields and align them nicely, like timestamp, logger, message
  • color coding for message severity, like bright red for ERROR
  • set column order: move a column out of view if it is not relevant to you.
  • filter out messages, like: block all messages from logger com.microsoft.alm.

Apache Chainsaw is such a tool.

Why choose Apache Chainsaw? First of all it is free. Second, it is a companion to the log4j library that is used by MPS. Chainsaw is designed to play nice with log4j. Third, it has been around for a long time, so it can be expected to offer relevant functionality. As a disclaimer: I myself have not used chainsaw before.

How to configure Chainsaw? Let’s make a choice here: we are going to connect Chainsaw to the MPS log via the file system, not via sockets. Sure, the log4j architecture offers a socket based approach, but that is much more involved. It would require configuration changes at the MPS side of things, whereas using the log file only requires a proper configuration at the Chainsaw side. Moreover, changing the configuration at the MPS side has the difficulty that the log4j version that MPS uses is way beyond end-of-life, making it difficult to find the proper components and documentation. MPS still uses log4j version 1.2.17 released Jan 2013 and log4j version 1 was declared end of life in 2015. I briefly tried to get the sockets running anyway but I did not succeed. Maybe at a later time.

It proved not to be very difficult to get Chainsaw to connect to the MPS log file. First, a short explanation if you want quick results. Second, a longer explanation if you want to know how this works under the hood. Finally the details if you want to explore further.

HOWTO – the short explanation

This XML snippet tells Chainsaw where to find the MPS log file and how to parse it.

<plugin class="org.apache.log4j.chainsaw.vfs.VFSLogFilePatternReceiver" name="MPS">
   <param name="appendNonMatches" value="true" />
   <param name="autoReconnect" value="true" />
   <param name="fileURL" value="file:/C:/Users/jgee/.MPS-19.1.1.149-c743b9d/system/log/idea.log" />
   <param name="logFormat" value="TIMESTAMP [PROP(RELATIVETIME)] LEVEL - LOGGER - MESSAGE" />
   <param name="name" value="MPS" />
   <param name="promptForUserInfo" value="false" />
   <param name="tailing" value="true" />
   <param name="timestampFormat" value="yyyy-MM-dd HH:mm:ss,SSS" />
   <param name="waitMillis" value="2000" />
</plugin>

Steps:

  1. Adapt the ‘fileURL’ parameter to your situation: 1/ change the user name “jennek” to yours 2/ change the MPS version “2019.1” to yours. Check if you can find the log file at this path. If it is not there, please read the longer explanation
  2. Open the default configuration file of Chainsaw and add the XML snippet. This file is named “receiver-config.xml” and it should be in folder “.chainsaw ” in your home directory. If it is not there, please read the longer explanation.
  3. Restart Chainsaw. You should now see a tab named file-/C:/Users/jennek/.MPS2019.1/system/log/idea.log. Tweak the view to your liking using the menu item “Tab Preferences” under the “Current Tab” menu. Your tweaks are persisted by Chainsaw.

One more thing. In the logger column, you may see weird entries like m.microsoft.alm.plugin.operations.BuildStatusLookupOperation. This is caused by MPS using a 60 character limitation on the logger name, truncating com.microsoft to m.microsoft. This results in quite a few spurious loggers in the Logger Tree Pane on the left. If you want to fix this, do this:

  1. Open <MPS-home>/bin/log.xml in your favorite editor
  2. Find the appender element with <param name="file" value="$LOG_DIR$/idea.log"/>
  3. Just below the line find this line <param name="ConversionPattern" value="%d [%7r] %6p - %30.30c - %m \n"/>
  4. Remove the 30.30 which means: “minimum field width 30, maximum field width 30 more”, and be sure to keep the %c

Now MPS will write the logger name to the log file without truncation.

Under the Hood – the longer explanation

To understand how Chainsaw should read the log file, let us look at how MPS writes the log file. As said, MPS uses log4j version 1. The log4j configuration is typically found in a file named log4j.xml but in the MPS distribution you will not find this file. Instead MPS has a file named log.xml in the /bin directory that is very similar to a log4j.xml file. This file contains a number of path variables that need to be expanded. Only after expansion the log.xml file is passed to log4j. To see this in action, read the gory details down below.

The file log.xml contains this piece of xml

<appender name="FILE" class="org.apache.log4j.RollingFileAppender">
   <param name="MaxFileSize" value="1Mb" />
   <param name="MaxBackupIndex" value="3" />
   <param name="file" value="$LOG_DIR$/idea.log" />
   <layout class="org.apache.log4j.PatternLayout">
      <param name="ConversionPattern" value="%d [%7r] %6p - %30.30c - %m \n" />
   </layout>
</appender>

This is the part that tells log4j to append log messages using a rolling file mechanism. The file parameter with value $LOG_DIR$/idea.log says to which file to append– where the $LOG_DIR$ is expanded. The ConversionPattern tells that the log message must be formatted in a specific way. This is precisely the information that Chainsaw needs to find the file and to split the log line into separate fields.

Here Chainsaw makes life easy for us. It would be a burden to first look at the conversion pattern of the appender that combines the message fields into a line and then to construct the inverse pattern to unravel this line into separate fields. Chainsaw will do this for us. Try this in Chainsaw (see screenshot below):

  1. Pick menu item “Load Chainsaw Configuration” under menu “File”
  2. Select “Use fileappender entries from a log4j config file”
  3. Press”Open File…” and navigate to the log.xml file in the bin folder of your MPS install
  4. Press “Save configuration as…” and navigate to some temporary folder and save as -say- mps.xml

Open mps. xml in your favorite editor and there you have it: Chainsaw has written the receivers (plugin) for the senders (appenders) in log.xml. The plugin we need is the one with “$LOG_DIR$/idea.log” in the element with name “fileURL”. See below.

<plugin class="org.apache.log4j.chainsaw.vfs.VFSLogFilePatternReceiver" name="FILE">
   <param name="appendNonMatches" value="true" />
   <param name="autoReconnect" value="true" />
   <param name="fileURL" value="file:/C:/path/to/chainsaw/bin/$LOG_DIR$/idea.log" />
   <param name="logFormat" value="TIMESTAMP [PROP(RELATIVETIME)] LEVEL - LOGGER - MESSAGE  " />
   <param name="name" value="FILE" />
   <param name="promptForUserInfo" value="false" />
   <param name="tailing" value="true" />
   <param name="timestampFormat" value="yyyy-MM-dd HH:mm:ss,SSS" />
   <param name="waitMillis" value="2000" />
</plugin>

But before we can use it we need to fix a few things

  1. in the element with the name “fileURL”, replace the path with $LOG_DIR$ with the path on your system. See the HOWTO section above.
  2. in the element with name “logFormat”, delete the ” ” — this is a bug. If you keep it, the splitting of a log line into fields fails and the entire log line ends up in the message column in Chainsaw

After these edits you should have an XML snippet at the beginning of this post. This snippet you may include in a Chainsaw configuration file — either the one that is loaded when Chainsaw starts up or one that you load on demand. To find the start-up configuration of Chainsaw, do this:

  1. Pick menu item “Show Application-wide Preferences…” under menu “View”
  2. use the path in the “Auto Config URL” under the tab “General”, typically file:/C:/Users/<username>/.chainsaw/receiver-config.xml

Logging log4j itself – for further exploration

If you want to explore how the log4j system is behaving, try this:

  1. find the file that launches MPS, on Windows this is <MPS-home>/bin/mps.bat
  2. where you see javaw.exe, remove the w and keep the java.exe.

This keeps the console window open while running MPS, showing all the logging from MPS. However this may slow down the IDE considerably. This is one good reason to view the log with Chainsaw instead. Now when you start up MPS you see that the very first lines are:

log4j:WARN No appenders could be found for logger (jetbrains.mps.util.ClassPathReader).
log4j:WARN Please initialize the log4j system properly.
og4j:WARN See http://logging.apache.org/log4j/1.2/faq.html#noconfig for more info.

Apparently log4j is looking for the default log4j.xml configuration file and complains it cannot find it. This is by design as discussed above.
Next try this:

  1. edit <MPS-home>/bin/mps.bat again
  2. add -Dlog4j.debug like this
    start "" "%JAVA_EXE%" %ALL_JVM_ARGS% -Dlog4j.debug -Didea.main.class.name=...

This forces log4j to provide logging at the debug level. Now when you start up MPS you see lines like

log4j: Class name: [org.apache.log4j.RollingFileAppender]
log4j: Setting property [maxFileSize] to [1Mb].
log4j: Setting property [maxBackupIndex] to [3].
log4j: Setting property [file] to [C:\Users\jennek\.MPS2019.1\system\log/idea.log].
log4j: Parsing layout of class: "org.apache.log4j.PatternLayout"
log4j: Setting property [conversionPattern] to [%d [%7r] %6p - %30.60c - %m
].
log4j: setFile called: C:\Users\jennek\.MPS2019.1\system\log/idea.log, true
log4j: setFile ended

This indicates that log4j actually now is processing the log.xml file. This info is useful when you start tweaking the MPS log.xml file.

Finally, in case you wondered, the log window in the IDE is also part of the log4j configuration but there is no entry for it in the log.xml file. The appender for this is created programmatically while the IDE is launching ( source: https://mps-support.jetbrains.com/hc/en-us/community/posts/207463965-Logging-Mechanism-in-MPS)

Happy logging!

Leave a Comment