Finding the Bad Apple in JVM

If you run into situation where you have to troubleshoot a JVM that consumes high CPU and you have absolutely no idea whats causing it, here are some very useful tricks that saved my life countless time.

top:
Most of us use Top often but there are some handy params that can be even more helpful.

First Do a top to get the Cpu Hungry process id.

#top
top - 14:33:22 up 42 days, 7:11, 2 users, load average: 1.60, 1.62, 1.56
Tasks: 154 total, 1 running, 153 sleeping, 0 stopped, 0 zombie
Cpu(s): 77.8%us, 0.8%sy, 0.0%ni, 21.5%id, 0.0%wa, 0.0%hi, 0.0%si, 0.0%st
Mem: 8061328k total, 7545548k used, 515780k free, 134776k buffers
Swap: 2097148k total, 162800k used, 1934348k free, 798096k cached</code>

PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND
12058 root 20 0 13.3g 4.7g 21m S 302.0 61.5 41219:31 java
18205 root 20 0 4273m 948m 6244 S 11.3 12.0 1704:03 java
12056 root 20 0 22032 1080 920 S 0.7 0.0 62:33.48 wrapper-linux-x
1 root 20 0 19356 1244 1052 S 0.0 0.0 0:03.22 init
2 root 20 0 0 0 0 S 0.0 0.0 0:00.00 kthreadd

Ok, clearly, the process with PID 12058 isn’t behaving properly.

Lets ask ‘top’ to list the child-process (one to one binding with each thread in JVM) for PID 12058

-H Flags turns on the Threads Toggle
-H : Threads toggle
Starts top with the last remembered ’H’ state reversed. When this toggle is On, all individual threads will be displayed. Other-
wise, top displays a summation of all threads in a process.

## top -p 12058 -H (-p only lists child process for 12058 )

&nbsp;

[mule@FSASYDESBPROD02 ~]# top -p $PID -H
top - 15:09:49 up 42 days, 7:48, 2 users, load average: 1.34, 1.50, 1.54
Tasks: 5359 total, 3 running, 5356 sleeping, 0 stopped, 0 zombie
Cpu(s): 77.8%us, 1.2%sy, 0.0%ni, 20.9%id, 0.0%wa, 0.0%hi, 0.1%si, 0.0%st
Mem: 8061328k total, 7740576k used, 320752k free, 135436k buffers
Swap: 2097148k total, 162652k used, 1934496k free, 833864k cached

PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND
28255 root 20 0 13.3g 4.9g 21m R 98.3 63.3 10163:33 java
14064 root 20 0 13.3g 4.9g 21m R 97.7 63.3 14089:00 java
14062 root 20 0 13.3g 4.9g 21m R 97.4 63.3 14073:55 java
925 root 20 0 13.3g 4.9g 21m S 1.9 63.3 279:22.62 java
12060 root 20 0 13.3g 4.9g 21m S 0.6 63.3 108:39.51 java

Ok, so Thread $28255 & $14064 is doing a lot of stuff. How do we know what they are doing??

jstack in rescue !

"AsyncLoggerConfig-1" daemon prio=10 tid=0x00007f45ec2ab000 nid=0x2f27 waiting on condition [0x00007f45e1e22000]
java.lang.Thread.State: WAITING (parking)
at sun.misc.Unsafe.park(Native Method)
- parking to wait for (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject)
at java.util.concurrent.locks.LockSupport.park(LockSupport.java:186)
at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:2043)
at com.lmax.disruptor.BlockingWaitStrategy.waitFor(BlockingWaitStrategy.java:45)
at com.lmax.disruptor.ProcessingSequenceBarrier.waitFor(ProcessingSequenceBarrier.java:55)
at com.lmax.disruptor.BatchEventProcessor.run(BatchEventProcessor.java:123)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
at java.lang.Thread.run(Thread.java:745)

In the jstack trace, the nid=0x2f27 is the hex of the pid we received before. So lets awk it!

bash# PID=12058
bash# NID=28255
bash# jstack $PID | awk '/ nid='"$(printf '%#x' $NID)"' /,/^$/'</code>

"pool-1140-thread-1" prio=10 tid=0x00007f45706b4000 nid=0x6e5f runnable [0x00007f453247a000]
java.lang.Thread.State: RUNNABLE
at sun.reflect.Reflection.getCallerClass0(Native Method)
at sun.reflect.Reflection.getCallerClass(Reflection.java:69)
at sun.reflect.GeneratedMethodAccessor1.invoke(Unknown Source)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:606)
at org.apache.logging.log4j.util.ReflectionUtil.getCallerClass(ReflectionUtil.java:123)
at org.apache.logging.log4j.util.ReflectionUtil.getCallerClass(ReflectionUtil.java:230)
at org.apache.logging.log4j.jul.AbstractLoggerAdapter.getContext(AbstractLoggerAdapter.java:34)
at org.apache.logging.log4j.spi.AbstractLoggerAdapter.getLogger(AbstractLoggerAdapter.java:42)
at org.apache.logging.log4j.jul.LogManager.getLogger(LogManager.java:89)
at java.util.logging.LogManager.demandLogger(LogManager.java:430)
at java.util.logging.Logger.demandLogger(Logger.java:346)
at java.util.logging.Logger.getLogger(Logger.java:393)
at com.orientechnologies.common.log.OLogManager.log(OLogManager.java:103)
at com.orientechnologies.common.log.OLogManager.debug(OLogManager.java:128)
at com.orientechnologies.orient.client.remote.OStorageRemote.useNewServerURL(OStorageRemote.java:1703)
- locked (a java.util.ArrayList)
at com.orientechnologies.orient.client.remote.OStorageRemote.getAvailableNetwork(OStorageRemote.java:1866)
at com.orientechnologies.orient.client.remote.OStorageRemote.openRemoteDatabase(OStorageRemote.java:1608)
at com.orientechnologies.orient.client.remote.OStorageRemote.open(OStorageRemote.java:216)
at com.orientechnologies.orient.client.remote.OStorageRemoteThread.open(OStorageRemoteThread.java:87)
at com.orientechnologies.orient.core.db.document.ODatabaseDocumentTx.open(ODatabaseDocumentTx.java:244)
at com.orientechnologies.orient.core.db.OPartitionedDatabasePool$DatabaseDocumentTxPolled.internalOpen(OPartitionedDatabasePool.java:137)
at com.orientechnologies.orient.core.db.OPartitionedDatabasePool.openDatabase(OPartitionedDatabasePool.java:331)
at com.orientechnologies.orient.core.db.OPartitionedDatabasePool.acquire(OPartitionedDatabasePool.java:304)
at com.tinkerpop.blueprints.impls.orient.OrientBaseGraph.(OrientBaseGraph.java:166)
at com.tinkerpop.blueprints.impls.orient.OrientGraphNoTx.(OrientGraphNoTx.java:54)
at com.tinkerpop.blueprints.impls.orient.OrientGraphFactory.getNoTx(OrientGraphFactory.java:93)
at au.com.foxsports.subscription.service.SubscriptionServiceImpl.getSubscribersWithRetry(SubscriptionServiceImpl.java:760)
at au.com.foxsports.subscription.service.SubscriptionServiceImpl.getSubscribers(SubscriptionServiceImpl.java:739)
at au.com.foxsports.subscription.service.SubscriptionServiceImpl$1.call(SubscriptionServiceImpl.java:945)
at java.util.concurrent.FutureTask.run(FutureTask.java:262)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
at java.lang.Thread.run(Thread.java:745)

There you go! You can see the 3rd party system eating up the CPU ! In my case its Orientdb. Yes, we faced a lot of issue trying to implement a graph model in orientdb, but thats a story for another day.

Troubleshooting Tomcat deployment problem for jaxws-2.2 application : The Sherlock Holmes way

I just spent my last 3 hour trying to deploy my perfect JAXWS-2.2 application in tomcat 6.0.26. Again I felt so great and thanked God that I took programming as a profession. Sure you don’t get to solve mysterious murder cases like Sherlock Homes, but the things we do are not much different! Where else can you go to work, get a problem with a set of clues, judge / discard / follow each and every clue, follow the trails to come to identify the problem and fix it and get paid for it!

Background:

The application was running happily in Jetty ever since I wrote it three months ago but my client wants to run it in tomcat. It was a standard web application so I thought it will be a child’s play to deploy it in tomcat. Ah! As if I have learned nothing from history! Nothing is child’s play when it comes to deploy an application in a new container, no matter how standard it is! I have learned this lesson hard way from deploying application in tomcat, jetty, jboss, weblogic, glassfish (yeah..i’v been fortunate/unfortunate enough to play with them all) , yet I tend to forget.

Problem 1:
First time I tried to run the app, I ran into the ClassNotFoundException:


SEVERE: WSSERVLET11: failed to parse runtime descriptor: java.lang.NoClassDefFoundError: javax/xml/ws/soap/AddressingFeature$Responses
java.lang.NoClassDefFoundError: javax/xml/ws/soap/AddressingFeature$Responses
	at com.sun.xml.ws.policy.PolicyWSDLGeneratorExtension.loadConfigurators(PolicyWSDLGeneratorExtension.java:459)
	at com.sun.xml.ws.policy.PolicyWSDLGeneratorExtension.start(PolicyWSDLGeneratorExtension.java:111)

..........................

I remember this! This was due to the jaxws-2.2 libraries conflicting with jaxws-2.1 libraries shipped with jdk-1.6! But I had it fixed by placing the latest jaxb-api.jar & jaxws-api.jar into the JDK_HOME/jre/lib/endorsed folder!

Hmm…here is a clue…the library is setup properly in JDK , app is running fine with Jetty with the same JDK, but wouldn’t load in tomcat!! Who is the ‘Usual Suspect’ ? Of course the tomcat classloading framework! Its ignoring the ‘endorsed’ jars configured in JDK ! Ah, at this point I begin to miss my old complex Tomcat 5.5, there was this ‘endorsed’ directory in the ‘common/endorsed’ folder. Where is it in tomcat 6? Luckily I had some old trick under my belt…Quickly Added a ServletContextListener like this:

public class WebappLoadListener implements ServletContextListener {
	private static final Log log = LogFactory.getLog(WebappLoadListener.class);
	public void contextDestroyed(ServletContextEvent arg0) {
	}

	public void contextInitialized(ServletContextEvent arg0) {
		log.info("\n\n\n ENDORSED DIR: " +System.getProperty("java.endorsed.dirs"));		
	}
}

And the output was:

ENDORSED DIR:  /usr/local/development/servers/apache-tomcat-6.0.26/endorsed

How the hack am I supposed to know that, the directory is not even there! Come on tomcat guys, I understand you want to make things simple for the new tomcat adopters, but why screw us – the old 5.5 users!!! Created folder “/usr/local/development/servers/apache-tomcat-6.0.26/endorsed” and copied the latest jars (jaxb-api.jar jaxws-api.jar) in there, got rid of the ClassNotFoundException.

Problem 2:
As soon as I got rid of problem 1, I ran into this:

SEVERE: WSSERVLET11: failed to parse runtime descriptor: java.lang.NoSuchMethodError: com.sun.istack.logging.Logger.getLogger(Ljava/lang/Class;)Lcom/sun/istack/logging/Logger;
java.lang.NoSuchMethodError: com.sun.istack.logging.Logger.getLogger(Ljava/lang/Class;)Lcom/sun/istack/logging/Logger;
	at com.sun.xml.ws.api.config.management.policy.ManagementAssertion.<clinit>(ManagementAssertion.java:87)
	at com.sun.xml.ws.server.MonitorBase.createManagedObjectManager(MonitorBase.java:121)
	at com.sun.xml.ws.server.WSEndpointImpl.<init>(WSEndpointImpl.java:143)
	at com.sun.xml.ws.server.EndpointFactory.createEndpoint(EndpointFactory.java:232)
	at com.sun.xml.ws.api.server.WSEndpoint.create(WSEndpoint.java:505)
	at com.sun.xml.ws.transport.http.DeploymentDescriptorParser.parseAdapters(DeploymentDescriptorParser.java:253)
	at com.sun.xml.ws.transport.http.DeploymentDescriptorParser.parse(DeploymentDescriptorParser.java:147)

Now this got my head spinning! All the clue I got from Google was pointing to ‘Problem 1’…I was also a little confused and headed that way, placed the ‘jaxb-api.jar jaxws-api.jar’ in various locations, with no luck ! Ok, time to give up that trail and think clear. So, it was not a ClassNotFoundException, the class is there, but the Method is not. Why do this sounds familier? Because I have seen it countless times! Its because of two version of same class staying in the classpath and the faulty one getting preference by Tomcat ClassLoader! If you know about tomcat classloading, you know that it creates a ClassLoader for each webapp and the jars in “WEB-INF/lib” are loaded first (by the child classloader). So I must have some jar in my dependency which should not be there…Hmm..how do I know which jar? Wait, I know a way, infact I even blogged about it HERE.

So quickly added this method in my WebappLoadListener:

public static String getClassLocation(Class clazz) {
		if(clazz == null) {
			return null;
		}

		try {
			ProtectionDomain protectionDomain = clazz.getProtectionDomain();
			CodeSource codeSource = protectionDomain.getCodeSource();
			URL location = codeSource.getLocation();
			return location.toString();
		} catch (Throwable e) {
			e.printStackTrace();
			return "Not found";
		}
	}

	public void contextInitialized(ServletContextEvent arg0) {		
		log.error("jar file: " + getClassLocation(com.sun.istack.logging.Logger.class));		
	}

OUTPUT:

ERROR WebappLoadListener:21 - jar file: file:/home/sajid/workspace_test/.metadata/.plugins/org.eclipse.wst.server.core/tmp0/wtpwebapps/jaxws-sample/WEB-INF/lib/istack-commons-runtime-1.1-SNAPSHOT.jar

I got you “Professor Moriarty” (in case you are not familiar with Sherlock Holmes, Professor Moriarty is the common villain)! How did you got in my LIB folder ! The very name “istack-commons-runtime-1.1-SNAPSHOT.jar” suggests that I should not bundle it in my app! I deleted the jar manually and ran the code. Ah! Sweet. At last my code deployed in tomcat and all my SOAP-UI tests(only Three to be honest) are passed! And where is the class loaded from now?

ERROR WebappLoadListener:21 - jar file: file:/home/sajid/workspace_test/.metadata/.plugins/org.eclipse.wst.server.core/tmp0/wtpwebapps/jaxws-sample/WEB-INF/lib/jaxb-impl-2.2.jar

See! The right class is supplied with the jaxb-impl Jar.

Now, back to the old question, how did istack-commons-runtime-1.1-SNAPSHOT.jar ended up in my library? Did a quick ‘Dependency Graph’ in eclipse

So I added an exclusion rule in the dependency of jaxws-rt:


		<dependency>
			<groupId>com.sun.xml.ws</groupId>
			<artifactId>jaxws-rt</artifactId>
			<version>2.2</version>
			<exclusions>
				<exclusion>
					<groupId>com.sun.istack</groupId>
					<artifactId>istack-commons-runtime</artifactId>
				</exclusion>
			</exclusions>
		</dependency>

Ran all the tests and everything seemed to be OK. I feel so lucky that I spent time writing those SOAP-UI test cases (at the time it felt like complete waste of time)! Otherwise, I’d have to test the application manually to see if anything was broken by this.

Conclusion:
I see now why newbies like to adopt those exotic Ruby framework instead of Java. Imagine someone trying to build a webservice using JAX-WS. As if the api specs are not confusing enough, he has to go through all these pain to run the app! I feel sorry for the poor guy if he starts with tomcat, he would have no clue that its not his code’s fault that the app is not running. Luckily I started with Jetty, not because I was wise but because the client wanted it in Jetty.

But did I have fun going through all these pain? I sure did 🙂 . Good to know that I still get a kick out of fixing these weird problems, no matter how many times I did it before.

Exporting Spring Beans as JMX Mbeans

If you always want to stay on top of your production system and always want to know whats going on in your APP, you would want to configure JMX for your application.

First you need to start your JVM with the following parameters to enable any JMX client to connect to your system.

-Dcom.sun.management.jmxremote.port=8888 -Dcom.sun.management.jmxremote.authenticate=false -Dcom.sun.management.jmxremote.ssl=false

This is just done without any security but in production, you would want to add authentication.

Now, add these configuration for your spring APP to automatically expose your Spring Beans as MBeans if they have the right annotations.

	<bean id="exporter" class="org.springframework.jmx.export.MBeanExporter"
		lazy-init="false">
		<property name="autodetect" value="true"></property>
		<property name="namingStrategy" ref="namingStrategy"></property>
		<property name="assembler" ref="assembler"></property>		
		<property name="server" ref="mbeanServer"></property>		
	</bean>

	<bean id="assembler"
		class="org.springframework.jmx.export.assembler.MetadataMBeanInfoAssembler">
		<property name="attributeSource" ref="attributeSource" />
	</bean>

	<bean id="namingStrategy"
		class="org.springframework.jmx.export.naming.MetadataNamingStrategy">
		<property name="attributeSource" ref="attributeSource" />
	</bean>

	<bean id="mbeanServer" class="java.lang.management.ManagementFactory" factory-method="getPlatformMBeanServer"/>	

The ‘exporter’ will inspect all your defined Spring Beans in your configuration and see if the have Spring JMX annotations. Now you need to define your beans with Annotations.

@ManagedResource(objectName = "yourapp:name=log4jLevelChanger", description = "LOG4j Level Changer")
public class Log4jLevelChanger  {
	private static final Log log = LogFactory.getLog(Log4jLevelChanger.class);
	
	public void init() throws AttributeNotFoundException, InstanceNotFoundException, MBeanException, ReflectionException {
		ArrayList<MBeanServer> servers = MBeanServerFactory.findMBeanServer(null);
		for(MBeanServer server : servers) {
			String name = (String) server.getAttribute(MBeanServerDelegate.DELEGATE_NAME,
            "MBeanServerId");	
			
			log.info("found  server: " + name);
		}
	}
	
	/*
	 * (non-Javadoc)
	 * 
	 * @see
	 * com.vantage.callcenter.web.utils.Log4jLevelChanger#setLogLevel(java.lang
	 * .String, java.lang.String)
	 */
	@ManagedOperation
	@ManagedOperationParameters({
	@ManagedOperationParameter(description="Name of the Logger to configure", name="loggerName"),
	@ManagedOperationParameter(description="Level ofthe Logger to set", name="level")
	})
	public void setLogLevel(
			
			String loggerName, 
			
			String level) {
		if ("debug".equalsIgnoreCase(level)) {
			Logger.getLogger(loggerName).setLevel(Level.DEBUG);
		} else if ("info".equalsIgnoreCase(level)) {
			Logger.getLogger(loggerName).setLevel(Level.INFO);
		} else if ("error".equalsIgnoreCase(level)) {
			Logger.getLogger(loggerName).setLevel(Level.ERROR);
		} else if ("fatal".equalsIgnoreCase(level)) {
			Logger.getLogger(loggerName).setLevel(Level.FATAL);
		} else if ("warn".equalsIgnoreCase(level)) {
			Logger.getLogger(loggerName).setLevel(Level.WARN);
		}
	}

        //Read the log4j.properties to reconfigure the logging levels.
	@ManagedOperation
	public boolean refreshLogging() {
		try {
			Log4jConfigurer.initLogging("classpath:log4j.properties");			
			return true;
		} catch (FileNotFoundException e) {
			return false;
		}
	}
	
	
	@ManagedOperation
	@ManagedOperationParameters ({
		@ManagedOperationParameter(description="Name of the Logger to get the Level", name="loggerName")	
	})
	public String getLogLevel(
			
			String loggerName) {
		log.debug("getLogLevel -> loggerName: " + loggerName);
		Logger logger = Logger.getLogger(loggerName);
		
		if(logger != null) {
			if(logger.getLevel() != null) {
				return logger.getLevel().toString();
			}
		}
		
		return Logger.getRootLogger().getLevel().toString();
	}
}

and define it in your application-context.xml as a regular bean

<bean id="log4jLevelChanger"  class="com.test.Log4jLevelChanger"></bean>

Thats it! Now you can open any Standard JMX client (JConsole / VisualVM / JManage) to inspect the bean and changing log levels!

You can also add Mbean Annotations to any regular Bean that you wish to inspect at runtime. For example, you can add it to the bean that manages your threadpool to see its utilization at runtime, you can add it to any in memory cache to find out memory leaks. If you think closely, the possibilities can be endless!

How to get the jar file location of a loaded class?

When there are two versions of the same class (same class & package name) in the classpath (may be from two different jars), there is no way to tell the JVM which one to load at runtime (JVM loads the one which it finds first). And there is no direct way of knowing from which jar the class was loaded! This causes enormous difficulties for a j2ee developer when working with different containers.

You can use the following code to find which jar was used to load the class

	public static String getClassLocation(Class clazz) {
		if(clazz == null) {
			return null;
		}
		
		try {
			ProtectionDomain protectionDomain = clazz.getProtectionDomain();
			CodeSource codeSource = protectionDomain.getCodeSource();
			URL location = codeSource.getLocation();
			return location.toString();
		} catch (Throwable e) {
			e.printStackTrace();
			return "Not found";
		}
	}

For example, The if you run the following code,

	public static void main(String[] args) {
		System.out.println("class location of Log: " + getClassLocation(org.apache.commons.logging.Log.class));
	}

It will give you :

class location of Log: file:/C:/dev/tools/maven2/repository/commons-logging/commons-logging/1.1.1/commons-logging-1.1.1.jar

This simple code helped me a lot to resolve a lot of deployment problem in different containers specially when working with third party libs.

Spring Session Scoped Bean

I have always hated direct usages of “HttpSession”. You know how tricky it becomes when you want to do advanced things like session replications / caching etc. I have previously used home grown session factory abstraction. But just recently I came across Spring “Session Scoped Bean”. So far, we have only used dependency injection of spring beans which had only 2 scopes – singleton & prototype. But now spring supports custom scopes for beans and one of them is “Session”. It means that this bean is created when a new HttpSession is created and preserved as long as the HttpSession is valid. Spring uses AOP to extract the sessionId from the httprequest and manage the lifecycle of the bean. So instead of putting your object directly into the session, you get to put them in an injected POJO based placeholder. This makes it easy to do the testing and getting rid of HttpSession dependency. So when time comes, you can use solutions like “terracotta” to distribute your session without changing your code! Isn’t that wonderful! Another niche Spring trick!

The details of how to setup the configurations can be found here. I followed the exact steps and it worked flawlessly.

UPDATE: How to Hotswap classes in the running jvm

If you have read my previous blog post about How to Hotswap classes in the running jvm, I am sure you will find Java Rebels even more interesting. It supports full class reloading support at runtime with method refactoring and all the stuffs that hotswap.jar could not do. Trust me, Java development has never been more fun. And if you are into spring development, it even supports spring configuration reloading without restarting the whole spring application context! Could it be better!!! I think its a must have feature for every java developer. I don’t know why sun is not incorporating this in the JVM? Just because java is not a scripting based language like php/ruby , doesn’t mean we can’t have fun like those guys! Speaking of fun, you can have some from this Java Rebel cartoon also

Only downside is JavaRebel is not free. There is a small fee that you have to pay. But let me tell you its worth it. And if you don’t trust me, you can always use the 30 Day trial version (although it will only take 3 days for you to become addicted to it).

NOTE: I don’t work for java rebel.I wish they took me in 🙂 it would be fun to develop such cool features that eases the life of so many developers.

How to redirect System.out.println in Java

Did you ever get frustrated with a codebase which has overuse of System.out.println??
May be it is flooding your console or even worse you need to capture the outputs to analyze them….Ever wondered how you can capture your System.out.println() ‘s of your tomcat application?? Well, you can always use IO Redirect in unix to send the output to a file. You can use find replace to change all System.out.println() to some method call which will write the logs to a file. But being the lazy programmer that I am, I always look for a shortcut. And sometimes I even find one 🙂
I was working with this code and it had important System.out.println everywhere. I wanted to use trail/grep and stuffs like that with the console logs but I couldn’t do that on the application console. So this is what I did to redirect all System.out.println to a log file.

public class MyMainClass {   public static void main(String[] args) throws FileNotFoundException {

    File file  = new File(\"/home/sajid/sysout.log\");   
    PrintStream printStream = new PrintStream(new FileOutputStream(file));

    System.out.println(\"1\");

    System.setOut(printStream);

    System.out.println(\"2\");

}}

Did you ever notice that System.out is just another PrintStream and you can replace it with your own? This is why I love java. You can replace many things with your own implementation. Did I tell you how I replaced the URLClassLoader with my JDBCClassLoader to load classes from Database? Lets keep that story for another post.

How to get the calling method information in Java

I was wondering around in a huge code base trying to figure out whats going on.
I wouldn’t say it was a bad code base, but it was done by a single geeky programmer who never cared about the readability because I guess he never thought anyone else would ever try to read it. Anyway, I could see all these meaningful log messages coming out from it but I didn’t know from where. I think he never heard of log4j or anything like that but luckily he used a class like this:

public class LogHelper{    
   public static void log(String log){

      System.out.println(log);  
   }
}

and used it like this:

public class X  { 
     public void doA() { 
        Logger.log("doing A"); 

        //..         
        //..         
        Logger.log("done doing A");
     }

     public void doB() {
	Logger.log("doing B");
        // 
        //

        Logger.log("done doing B");
     }
}

So he called this static log method from all over the code base to do the logging.
And the log looked like this:

   doing A
   doing B
   done doing B
   done doing A

I desperately wanted to know which class/method/line was calling this method like I am used to in log4j.

Then I thought the calling Thread has this information. The question is how can I get it! After playing a bit with stack information, I came up with this:

public static String getCallingMethodInfo() {  
  StackTraceElement[] stackTrace ;

  try{
      throw new Exception();  
  }
  catch (Exception e) { 
    stackTrace = e.getStackTrace();
  }

  if(stackTrace != null && stackTrace.length >= 2) {

     StackTraceElement s = stackTrace[2];  
  
     if(s != null) {

        return s.getClassName() + ".(" + s.getMethodName() +"):["+ s.getLineNumber() + "] -:";

     } 
  }

  return null;
}

So finally the log method looked like this:

public class LogHelper {  
 public static void log(String log){

      String caller = getCallingMethodInfo();  
      System.out.println(caller + ": " + log);

   }
}

So, finally the logs looked like this:

  X.(doA):[5]-: doing A
  X.(doB):[14]-: doing B
  X.(doA):[9]-: done doing A
  X.(doB):[18]-: done doing B

In jdk 1.5 you can actually get the stack information like this:

Thread.currentThread().getStackTrace()

but unfortunately I was working with a 1.4 codebase. But Throwing an exception and catching it back did the trick 🙂

Having said all that, It will be an insane idea to put this code to production. But can be very helpful when you are trying to understand the code.