Message debugging: Good idea but running out of memory

[tom08zehn]

My problem: I want easy debugging and follow a single message's log in the Mirth GUI. But Mirth logs contain lots of mixed up entries from different channels and messages and the GUI can only show the last 99 entries. All this makes debugging tough.

My idea: Collect the logs of one message programmatically and make it available in Dashboard's "Mapping" tab using a channelMap variable.

My solution:

• Create a logger per message (see here)
• Create a logger WriterAppender made of a StringWriter
• Store StringWriter in channelMap

In poetic words what's happening (code snippets below):

• Calling custom_logger() for the first time creates a logger named <channelName>[:<messageId> (if exists)]:<originalName>, example: MyChannel:324:preprocessor where 324 is the message ID
• custom_logger() invokes the call of add_logger_appender()
• add_logger_appender() creates a StringWriter, stores it in channelMap("__LOG__"), creates a WriterAppender and appends it to the current logger
• As a result, channelMap("__LOG__") contains a copy of the logger MyChannel:324:preprocessor
• The next time custom_logger is called, a new logger MyChannel:324:transformer is created
• When invoking add_logger_appender this time, the key channelMap ("__LOG__") already exists and the stored StringWriter living there is used to create a new WriterAppender that is appended to the current logger
• As a result, channelMap("__LOG__") now contains a copy of both loggers, MyChannel:324:preprocessor and MyChannel:324:transformer
• This is repeating through all stages of a channel and as long as the message lifecycle has ended
• As a result, channelMap("__LOG__") contains a copy of all loggers that belong to the same message (as the channelMap variable exists separately in the scope of each single message)

Problem with my solution: after some days I'm getting java.lang.OutOfMemoryError: Java heap space errors and Mirth crashes

Question 1: Do you have any idea why memory is running full? I was expecting that Java's garbage collector is cleaning up loggers, their appenders and channelMap variables including references to the StringWriters

Question 2: If - for any reason - it is "as is" and I need to clean up on my own, what's the best solution?

Error details (investigation of heap dump):

10,357 instances of java.io.StringWriter, loaded by <system class loader> occupy 178,279,392 (67.66%) bytes. 

These instances are referenced from one instance of java.util.Hashtable$Entry[], loaded by <system class loader>, which occupies 12,379,400 (4.70%) bytes.

Digging little bit deeper into the dump reveals that the Hashtable entries are not cleaned up properly. All of them contain java.io.StringWriters of the org.apache.log4j.Logger.

Code snippets:

Code Template Library custom_logger():

function custom_logger() {
	var originalName = logger.getName();
	var newName = [channelName, originalName];
	if(typeof connectorMessage !== "undefined") newName.splice(1, 0, connectorMessage.getMessageId()); // connectorMessage not exists in some scopes, e.g. deploy script
	newName = newName.join(":");

	var level = logger.getLevel();
	logger = org.apache.log4j.Logger.getLogger(newName); // override happens here
	logger.setLevel(level);
	
	// Add an appender to current logger (only in channel context, e.g. for debugging in Dashboard and automated testing)
	add_logger_appender();
}

// Automatically call it (works everywhere except transformers)
custom_logger();

Code Template Library add_logger_appender():

function add_logger_appender() {
	// Do nothing if channelMap not exists, e.g. in deploy script
	if(typeof channelMap == "undefined") return false;
	
	try {
		// Get existing Writer from channelMap (null if not given)
		var existingWriter = $c("__LOG__");
		
		// Use existing Writer if type of java.io.Writer, otherwise create new StringWriter
		var writer = existingWriter instanceof java.io.Writer ? existingWriter : new java.io.StringWriter();
		
		// Get layout of rootLogger's ArrayAppender
		var layout;
		var rootLogger = org.apache.log4j.LogManager.getRootLogger();
		var appenders = rootLogger.getAllAppenders();
		while(appenders.hasMoreElements()) {
			var appender = appenders.nextElement();
			if(appender instanceof com.mirth.connect.plugins.serverlog.ArrayAppender) {
				layout = appender.getLayout();
				break;
			}
		}
		
		// Cannot continue without layout
		if(!layout) return false;
		
		// Create new WriterAppender
		var appender = new org.apache.log4j.WriterAppender(layout, writer);
		
		// Add appender to current logger
		logger.addAppender(appender);
		
		// Store Writer in channelMap in key "__LOG__"
		$c("__LOG__", writer);
	} catch(e) {
		return false;
	}
	
	return true;
}

Channel transformer:

// first line in transformer code is:
custom_logger();

[jonbartels]

**Ignore this my idea was wrong. I was looking only at StringWriter and the map and ignoring that the writer has to exist for the log appender to work. **

I wonder if you're leaking memory because the connector map is going to keep that writer on live heap because its never closed by calling toString. Instantiating a writer shouldn't be expensive.

Instead of storing the writer object in memory try this:

function add_logger_appender() {
	// Do nothing if channelMap not exists, e.g. in deploy script
	if(typeof channelMap == "undefined") return false;
	
	try {
		// Get existing Writer from channelMap (null if not given)
		var existingLog = $c("__LOG__");
		
		// Use existing Writer if type of java.io.Writer, otherwise create new StringWriter
		var writer = new java.io.StringWriter();
		writer.append(existingLog);
		
		// Get layout of rootLogger's ArrayAppender
		var layout;
		var rootLogger = org.apache.log4j.LogManager.getRootLogger();
		var appenders = rootLogger.getAllAppenders();
		while(appenders.hasMoreElements()) {
			var appender = appenders.nextElement();
			if(appender instanceof com.mirth.connect.plugins.serverlog.ArrayAppender) {
				layout = appender.getLayout();
				break;
			}
		}
		
		// Cannot continue without layout
		if(!layout) return false;
		
		// Create new WriterAppender
		var appender = new org.apache.log4j.WriterAppender(layout, writer);
		
		// Add appender to current logger
		logger.addAppender(appender);
		
		// Store Writer in channelMap in key "__LOG__"
		$c("__LOG__", writer.toString());
	} catch(e) {
		return false;
	}
	
	return true;
}

If you do this does your memory leak go away or not?

[tom08zehn]

Hum, haven't yet tested but I think I understood the following would happen:

• channelMap("__LOG__") now is string type (which is good)
• you always create a new StringWriter and append to it whatever is in the existing log (a string)
• you create the logger appender using the StringWriter in the same way that I did
• you're closing the StringWriter by calling .toString() and store the result in channelMap("__LOG__")

I think it won't work because you immediately call .toString() directly after adding the appender. This will only rewrite the string in channelMap("__LOG__") with the same content (current state of the StringWriter ).

You don't give the StringWriter the chance to receive new lines from the appender.

But this will likely not cause a memory issue... but also not do the job.

I'm actually on holiday and will check after my return.

My idea is to create a custom appender and simply add the log line to the string in channelMap("__LOG__") , also see here