So soll Software *nicht* sein

Mein Mailarchivierungssystem ist seit dem 19. Dezember offline, das ist aber auch eben erst aufgefallen als ich „mal schnell“ eine bestimmte EMail aus dem Archiv benötigte.

Die Software für die Mailarchivierung ist a) gut b) als „pro“-Version recht teuer c) defacto auf einer ziemlich lazy zusammengestellter Ansammlung von unterschiedlichen Tools gegründet.

Nach viel suchen habe ich die Logfiles gefunden (nein, sie waren nicht in /var/log) und die sahen in etwa so aus:


Dec 31, 2015 3:29:53 AM org.apache.tomcat.util.digester.Digester fatalError

SEVERE: Parse Fatal Error at line 1 column 1: Premature end of file.
org.xml.sax.SAXParseException: Premature end of file.
at com.sun.org.apache.xerces.internal.util.ErrorHandlerWrapper.createSAXParseException(Unknown Source)
at com.sun.org.apache.xerces.internal.util.ErrorHandlerWrapper.fatalError(Unknown Source)
at com.sun.org.apache.xerces.internal.impl.XMLErrorReporter.reportError(Unknown Source)
at com.sun.org.apache.xerces.internal.impl.XMLScanner.reportFatalError(Unknown Source)
at com.sun.org.apache.xerces.internal.impl.XMLDocumentScannerImpl$PrologDriver.next(Unknown Source)
at com.sun.org.apache.xerces.internal.impl.XMLDocumentScannerImpl.next(Unknown Source)
at com.sun.org.apache.xerces.internal.impl.XMLDocumentFragmentScannerImpl.scanDocument(Unknown Source)
at com.sun.org.apache.xerces.internal.parsers.XML11Configuration.parse(Unknown Source)
at com.sun.org.apache.xerces.internal.parsers.XML11Configuration.parse(Unknown Source)
at com.sun.org.apache.xerces.internal.parsers.XMLParser.parse(Unknown Source)
at com.sun.org.apache.xerces.internal.parsers.AbstractSAXParser.parse(Unknown Source)
at com.sun.org.apache.xerces.internal.jaxp.SAXParserImpl$JAXPSAXParser.parse(Unknown Source)
at org.apache.tomcat.util.digester.Digester.parse(Digester.java:1663)
at org.apache.catalina.users.MemoryUserDatabase.open(MemoryUserDatabase.java:402)
at org.apache.catalina.users.MemoryUserDatabaseFactory.getObjectInstance(MemoryUserDatabaseFactory.java:103)
at org.apache.naming.factory.ResourceFactory.getObjectInstance(ResourceFactory.java:140)
at javax.naming.spi.NamingManager.getObjectInstance(Unknown Source)
at org.apache.naming.NamingContext.lookup(NamingContext.java:793)
at org.apache.naming.NamingContext.lookup(NamingContext.java:140)
at rg.apache.naming.NamingContextBindingsEnumeration.nextElementInternal(NamingContextBindingsEnumeration.java:113)
at org.apache.naming.NamingContextBindingsEnumeration.next(NamingContextBindingsEnumeration.java:71)
at org.apache.catalina.mbeans.GlobalResourcesLifecycleListener.createMBeans(GlobalResourcesLifecycleListener.java:137)
at org.apache.catalina.mbeans.GlobalResourcesLifecycleListener.createMBeans(GlobalResourcesLifecycleListener.java:109)
at org.apache.catalina.mbeans.GlobalResourcesLifecycleListener.lifecycleEvent(GlobalResourcesLifecycleListener.java:81)
at org.apache.catalina.util.LifecycleSupport.fireLifecycleEvent(LifecycleSupport.java:117)
at org.apache.catalina.core.StandardServer.start(StandardServer.java:703)
at org.apache.catalina.startup.Catalina.start(Catalina.java:578)
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at sun.reflect.NativeMethodAccessorImpl.invoke(Unknown Source)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(Unknown Source)
at java.lang.reflect.Method.invoke(Unknown Source)
at org.apache.catalina.startup.Bootstrap.start(Bootstrap.java:288)

Dec 31, 2015 3:29:53 AM org.apache.naming.NamingContext lookup
WARNING: Unexpected exception resolving reference
org.xml.sax.SAXParseException: Premature end of file.
at com.sun.org.apache.xerces.internal.parsers.AbstractSAXParser.parse(Unknown Source)
at com.sun.org.apache.xerces.internal.jaxp.SAXParserImpl$JAXPSAXParser.parse(Unknown Source)
at org.apache.tomcat.util.digester.Digester.parse(Digester.java:1663)
at org.apache.catalina.users.MemoryUserDatabase.open(MemoryUserDatabase.java:402)
at org.apache.catalina.users.MemoryUserDatabaseFactory.getObjectInstance(MemoryUserDatabaseFactory.java:103)
at org.apache.naming.factory.ResourceFactory.getObjectInstance(ResourceFactory.java:140)
at javax.naming.spi.NamingManager.getObjectInstance(Unknown Source)
at org.apache.naming.NamingContext.lookup(NamingContext.java:793)
at org.apache.naming.NamingContext.lookup(NamingContext.java:140)
at org.apache.naming.NamingContextBindingsEnumeration.nextElementInternal(NamingContextBindingsEnumeration.java:113)
at org.apache.naming.NamingContextBindingsEnumeration.next(NamingContextBindingsEnumeration.java:71)
at org.apache.catalina.mbeans.GlobalResourcesLifecycleListener.createMBeans(GlobalResourcesLifecycleListener.java:137)
at org.apache.catalina.mbeans.GlobalResourcesLifecycleListener.createMBeans(GlobalResourcesLifecycleListener.java:109)
at org.apache.catalina.mbeans.GlobalResourcesLifecycleListener.lifecycleEvent(GlobalResourcesLifecycleListener.java:81)
at org.apache.catalina.util.LifecycleSupport.fireLifecycleEvent(LifecycleSupport.java:117)
at org.apache.catalina.core.StandardServer.start(StandardServer.java:703)
at org.apache.catalina.startup.Catalina.start(Catalina.java:578)
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at sun.reflect.NativeMethodAccessorImpl.invoke(Unknown Source)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(Unknown Source)
at java.lang.reflect.Method.invoke(Unknown Source)
at org.apache.catalina.startup.Bootstrap.start(Bootstrap.java:288)
at org.apache.catalina.startup.Bootstrap.main(Bootstrap.java:413)

Dec 31, 2015 3:29:53 AM org.apache.catalina.mbeans.GlobalResourcesLifecycleListener createMBeans
SEVERE: Exception processing Global JNDI Resources
javax.naming.NamingException: Premature end of file.
at org.apache.naming.NamingContext.lookup(NamingContext.java:805)
at org.apache.naming.NamingContext.lookup(NamingContext.java:140)
at org.apache.naming.NamingContextBindingsEnumeration.nextElementInternal(NamingContextBindingsEnumeration.java:113)
at org.apache.naming.NamingContextBindingsEnumeration.next(NamingContextBindingsEnumeration.java:71)
at org.apache.catalina.mbeans.GlobalResourcesLifecycleListener.createMBeans(GlobalResourcesLifecycleListener.java:137)
at org.apache.catalina.mbeans.GlobalResourcesLifecycleListener.createMBeans(GlobalResourcesLifecycleListener.java:109)
at org.apache.catalina.mbeans.GlobalResourcesLifecycleListener.lifecycleEvent(GlobalResourcesLifecycleListener.java:81)
at org.apache.catalina.util.LifecycleSupport.fireLifecycleEvent(LifecycleSupport.java:117)
at org.apache.catalina.core.StandardServer.start(StandardServer.java:703)
at org.apache.catalina.startup.Catalina.start(Catalina.java:578)
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at sun.reflect.NativeMethodAccessorImpl.invoke(Unknown Source)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(Unknown Source)
at java.lang.reflect.Method.invoke(Unknown Source)
at org.apache.catalina.startup.Bootstrap.start(Bootstrap.java:288)
at org.apache.catalina.startup.Bootstrap.main(Bootstrap.java:413)

Aus dem Stackdump entnehme ich, dass der Programmierer an irgendeiner Stelle eine XML-Datei lesen möchte und das nicht funktionierte.

Es gibt an dieser Stelle drei Megafails:

  • erstens verlässt sich der Programmierer blind darauf, dass die Datei auswertbar ist und hat keine Vorsorge für den Fall getroffen, dass irgendwas nicht funktioniert.
  • zweitens haben sich die Programmierer des Appservers blind darauf verlassen, dass der Programmierer „in der höheren Ebene“ dafür sorgt, dass die fehlerhafte Datei mit Pfad und Name ins Logfile kommt
  • drittens haben solche kompletten Stacktraces nur was im Debugmode im Logfile zu suchen – entweder kommt eine ordentliche Fehlermeldung der Sorte „hier genau klemmts“ oder man kann den Kram auf den Einzeiler „keine Ahnung was los ist“ reduzieren.

    Den Fehler habe ich durch Induktion gefunden: Da weder Programm noch Konfigurationsdateien seit 4 Jahren angefasst wurden kann nur eine Datei kaputt sein, die Programmintern erzeugt wurde. Typischerweise dann, wenn Tool „A“ eine XML-Datei für Tool „B“ bereitstellt (eigentlich eine recht altväterliche Vorgehensweise, aber ….)

    Und da intern viel mit XML-Dateien gearbeitet wird, musste ich nur nach *.xml|*.XML an den Stellen suchen, wo die Software sich gewöhnlich verewigt.

    Und Tatsache – da war eine dieser „temporär erzeugten“ Zwischendateien. Im Source wird das wahrscheinlich so ausgesehen haben: „Wenns die Zwischendatei schon gibt, dann mache weiter“.

    Dumm ist nur, dass diese Zwischendatei leer war – erfahrene Programmierer haben an kritischen Stellen *immer* Prüfungen drin wie zb. „ist die Datei grösser als 0 Byte“ und „Ist die Datei grundsätzlich Parsbar“

  • Schreibe einen Kommentar

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

    *

    *