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:
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
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 :-).
War dieser Beitrag hilfreich?
Weitere Beiträge
von Thomas Jaspers
22.2.2019 Dein Job bei codecentric?
Jobs
Agile Developer und Consultant (w/d/m)
Alle Standorte
Weitere Artikel in diesem Themenbereich
Entdecke spannende weiterführende Themen und lass dich von der codecentric Welt inspirieren.
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-Autor*in
Thomas Jaspers
Du hast noch Fragen zu diesem Thema? Dann sprich mich einfach an.
Du hast noch Fragen zu diesem Thema? Dann sprich mich einfach an.