This is a mystery story of Jython, Hudson and Tomcat. Our environment for continuous integration is based on the Robot Framework and Hudson, where Hudson is running on a Tomcat-Server under Linux. From here our Robot-Tests are started and as we are implementing our Tests (Keywords) in Java we are using Jython for this.
This setup is working perfectly fine and offers very good functionality and comfort. This was unless “out of a sudden” the following problem (Port already in use: 6969) was showing up when executing any Robot tests on Hudson:
[workspace] $ /bin/sh -xe /opt/tomcat6/temp/hudson2344945468088750944.sh + jybot --version Could not load Logmanager "org.apache.juli.ClassLoaderLogManager" java.lang.ClassNotFoundException: org.apache.juli.ClassLoaderLogManager at java.net.URLClassLoader$1.run(URLClassLoader.java:200) at java.security.AccessController.doPrivileged(Native Method) at java.net.URLClassLoader.findClass(URLClassLoader.java:188) at java.lang.ClassLoader.loadClass(ClassLoader.java:307) at sun.misc.Launcher$AppClassLoader.loadClass(Launcher.java:301) at java.lang.ClassLoader.loadClass(ClassLoader.java:252) at java.util.logging.LogManager$1.run(LogManager.java:166) at java.security.AccessController.doPrivileged(Native Method) at java.util.logging.LogManager.<clinit>(LogManager.java:156) at java.util.logging.Logger.getLogger(Logger.java:273) at sun.management.snmp.util.MibLogger.<init>(MibLogger.java:57) at sun.management.snmp.util.MibLogger.<init>(MibLogger.java:42) at sun.management.jmxremote.ConnectorBootstrap.<clinit>(ConnectorBootstrap.java:760) at sun.management.Agent.startAgent(Agent.java:127) at sun.management.Agent.startAgent(Agent.java:239) Fehler: Agent-Ausnahmefehler : java.rmi.server.ExportException: Port already in use: 6969; nested exception is: java.net.BindException: Address already in use Finished: FAILURE
It was quite clear that something must have changed as in this world – and especially in software development – everything is based on reason and effect. We could see the effect very clearly so my collegue Andreas and me started to look for the reason.
An obvious approach here is to start the tests directly from the shell and thus by-passing Hudson. This works without any problems. So what is different when starting the tests using Hudson in comparison to starting the tests directly from the shell? To keep this story short let’s directly jump to the first major finding. For this it was (and is) extremely helpful that Jython can be started with a “-print” option to see the real Java command that is executed in the end. Starting the following command /opt/jython/jython –print /usr/lib/python2.4/site-packages/robot/runner.py from the shell we thus get:
/usr/java/jdk1.6.0_11/jre/bin/java -Xmx512m -Xss1024k -classpath /opt/jython/jython.jar: -Dpython.home=/opt/jython -Dpython.executable=/opt/jython/jython org.python.util.jython /usr/lib/python2.4/site-packages/robot/runner.py
This looks very good, which is not too surprising as this is working without problems anyway. Issuing the same command using Hudson we can see that there are quite some different parameters, amongst which we can also see the problematic one:
/usr/java/jdk1.6.0_11/jre/bin/java -Dcom.sun.management.jmxremote -Dcom.sun.management.jmxremote.port=6969 -Dcom.sun.management.jmxremote.ssl=false -Dcom.sun.management.jmxremote.authenticate=false -Djava.util.logging.manager=org.apache.juli.ClassLoaderLogManager -Xmx512m -Xss1024k -classpath /opt/jython/jython.jar: -Dpython.home=/opt/jython -Dpython.executable=/opt/jython/jython org.python.util.jython /usr/lib/python2.4/site-packages/robot/runner.py
The option “Dcom.sun.management.jmxremote.port=6969” is obviously the reason for the port conflict. Knowing this we take a closer look at the script that is used to start Jython. In this script (/opt/jython/jython we find the following line:
JAVA_OPTS=”$JAVA_OPTS $JAVA_MEM $JAVA_STACK”
This is influencing the Java parameters and the environment variable $JAVA_OPTS contains the wrong parameters, which are then passed to the Java execution.
For some unrelated project this variable has been set and exported in the Tomcat startup-script, which was then “passing” those values accidentally to Jython. And doing this had this fatal effect on our Robot tests and caused the port exception.
It is really always fascinating to see how a small change in one part of the system can cause trouble in other parts of the system that seems totally unrelated on first sight. In this case the problem was really hard to foresee. But if now someone is – by any chance – running into the same problem hopefully this mystery story is showing up in google to help.
The final solution was of course really trivial, because the exported $JAVA_OPTS variable was anyway no longer needed and could be removed. Otherwise the problem could have been fixed by patching the startup-script of Jython.
For us this was a really thrilling story that luckily ended with a happy end :-).