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:
1[workspace] $ /bin/sh -xe /opt/tomcat6/temp/hudson2344945468088750944.sh 2+ jybot --version 3Could not load Logmanager "org.apache.juli.ClassLoaderLogManager" 4java.lang.ClassNotFoundException: org.apache.juli.ClassLoaderLogManager 5 at java.net.URLClassLoader$1.run(URLClassLoader.java:200) 6 at java.security.AccessController.doPrivileged(Native Method) 7 at java.net.URLClassLoader.findClass(URLClassLoader.java:188) 8 at java.lang.ClassLoader.loadClass(ClassLoader.java:307) 9 at sun.misc.Launcher$AppClassLoader.loadClass(Launcher.java:301) 10 at java.lang.ClassLoader.loadClass(ClassLoader.java:252) 11 at java.util.logging.LogManager$1.run(LogManager.java:166) 12 at java.security.AccessController.doPrivileged(Native Method) 13 at java.util.logging.LogManager.<clinit>(LogManager.java:156) 14 at java.util.logging.Logger.getLogger(Logger.java:273) 15 at sun.management.snmp.util.MibLogger.<init>(MibLogger.java:57) 16 at sun.management.snmp.util.MibLogger.<init>(MibLogger.java:42) 17 at sun.management.jmxremote.ConnectorBootstrap.<clinit>(ConnectorBootstrap.java:760) 18 at sun.management.Agent.startAgent(Agent.java:127) 19 at sun.management.Agent.startAgent(Agent.java:239) 20Fehler: Agent-Ausnahmefehler : java.rmi.server.ExportException: Port already in use: 6969; nested exception is: 21 java.net.BindException: Address already in use 22Finished: 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 :-).
Was this post helpful?
More articles
fromThomas Jaspers
22.2.2019 Your job at codecentric?
Jobs
Agile Developer und Consultant (w/d/m)
Alle Standorte
More articles in this subject area
Discover exciting further topics and let the codecentric world inspire you.
Gemeinsam bessere Projekte umsetzen.
Wir helfen deinem Unternehmen.
Du stehst vor einer großen IT-Herausforderung? Wir sorgen für eine maßgeschneiderte Unterstützung. Informiere dich jetzt.
Hilf uns, noch besser zu werden.
Wir sind immer auf der Suche nach neuen Talenten. Auch für dich ist die passende Stelle dabei.
Blog author
Thomas Jaspers
Do you still have questions? Just send me a message.
Do you still have questions? Just send me a message.