Eine Detektivgeschichte über Jython, Hudson, Tomcat und port 6969

Keine Kommentare

Im Folgenden wird eine echte Detektivgeschichte erzählt mit Jython, Hudson und Tomcat in den Hauptrollen. Unsere Umgebung für kontinuierliche Integration basiert auf dem Robot Framework und Hudson. Dabei läuft der Hudson auf einem Tomcat-Server unter Linux. Von dort werden dann die Robot-Tests gestartet und da wir die Tests (Keywords) in Java implementieren wird hierzu Jython genutzt.


Dieses Setup funktioniert tadellos und bietet gute Funktionalität und Komfort, bis „auf einmal“ der folgende Fehler (Port already in use: 6969) beim Ausführen der Tests auftaucht:

[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

Es war klar, dass sich irgendwas geändert haben musste, denn auf dieser Welt – und insbesondere bei der SW-Entwicklung – beruht alles auf Ursache und Wirkung. Die Wirkung haben wir vor Augen, also gehen mein Kollege Andreas und ich auf die Suche nach der Ursache.

Ein naheliegender Versuch ist das starten der Tests direkt aus der Shell, ohne den Hudson zu benutzen. Dies funktioniert problemlos. Was also ist anders beim Start über Hudson als beim direkten Start aus der Shell? Damit die Geschichte nicht zu lang wird, springe ich direkt zum ersten wichtigen Finding. Hierbei ist es extrem nützlich, dass Jython mit einer „–print“ Option gestartet werden kann, um das final ausgeführte Java-Kommando zu sehen. In der Shell ergibt sich nach einem /opt/jython/jython –print /usr/lib/python2.4/site-packages/robot/runner.py:

/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

Sieht alles gut aus, naja kein Wunder, das funktioniert ja auch. Dasgleiche Kommando über den Hudson ausgeführt ergibt eine ganze Reihe anderer Parameter, darunter auch den Bösewicht dieser Geschichte:

/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

Der Bösewicht hier ist „Dcom.sun.management.jmxremote.port=6969“, der das Port-Problem offensichtlich verursacht. Mit diesem Wissen geht es in das Jython Shell-Skript, welches zum Start von Jython genutzt wird. Also ein gezielter Blick (naja, oder auch zwei oder drei) in /opt/jython/jython führt die folgende Zeile zu Tage:

JAVA_OPTS=“$JAVA_OPTS $JAVA_MEM $JAVA_STACK“

Hier werden die Java-Parameter beeinflusst, die Jython letzten Endes nutzt und die fehlerhaften Werte kommen offensichtlich aus der Umgebungsvariable $JAVA_OPTS.

In einer normalen Shell ist diese Variable nicht gesetzt und es gibt keine Probleme. Für ein anderes Projekt wurde aber in unserem Tomcat Startup-Script genau diese Umgebungsvariable gesetzt und exportiert. Und dabei wurde dann auch der – für die Robot-Tests fatale – Wert für den JMX Remote Port gesetzt.

Es ist schon immer wieder spannend, wie eine eigentlich kleine Änderung am System zu unerwarteten Seiteneffekten führen kann. Wobei dies wirklich kaum vorhersehbar war. Sollte aber jemand nun in das gleiche oder ein ähnliches Problem laufen, wird hoffentlich diese Detektivgeschichte in Google auftauchen. Die Lösung war am Ende natürlich einfach, denn es wurde der Export in Tomcat nicht (mehr) gebraucht und auch hätte dies leicht durch eine Änderung des Jython-Skripts gefixt werden können.

Für uns war es auf jeden Fall eine spannende Geschichte mit einem echten Happy End :-).

Thomas Jaspers

Langjährige Erfahrung in agilen Softwareprojekten unter Einsatz von Java-Enterprise-Technologien. Schwerpunkt im Bereich der Testautomatisierung (Konzepte und Open-Source Werkzeuge).

Share on FacebookGoogle+Share on LinkedInTweet about this on TwitterShare on RedditDigg thisShare on StumbleUpon

Kommentieren

Deine E-Mail-Adresse wird nicht veröffentlicht. Erforderliche Felder sind mit * markiert.