WebSocket und der Cluster

Früher in der guten alten Zeit waren Webanwendungen verbindungslos: Man hat eine Seite angefragt, die Seite wurde ausgeliefert und die Verbindung war beendet. Man hat was in Formulare eingetragen, auf „absenden“ gedrückt und die Verbindung war beendet. Genau darauf sind Applicationserver optimiert. Ok, es gab da noch diese Sache mit den Session Daten, die unter einem Session Schlüssel gespeichert wurden. Die haben schon jede Menge Ärger gemacht, wenn es um einen Cluster ging. Dafür gab es dann Mechanismen, die Daten auf alle Instanzen des Cluster verteilt haben oder zumindest Session affine Loadbalancer, die einen Request immer wieder auf die Clusterinstanz geschickt haben, auf der die Session auch tatsächlich war. Jetzt haben wir allerdings etwas lustigeres: permanente Verbindungen und die Möglichkeit, Daten zu dem Client aktiv zu pushen. Am niegelnagelneusten macht man das mit WebSockets, die seit Java EE 7 auch Teil des Standards sind.

Das funktioniert so weit auch alles erst einmal ganz prima, solange man die Event Architektur sofort bei Ankunft im WebSocket Endpoint vergisst und ab da alles schön synchron aufruft. Was aber, wenn man im Backend einen Event erzeugt und an das Frontend via WebSocket zurückschicken möchte?

CDI Events als Callback für WebSockets

Ich bin vor einiger Zeit über diesen Artikel gestolpert. Die wesentliche Idee ist, einen WebSocket Endpoint zu einem Observer für CDI Events zu machen. Das ist so von der Sache her schon einmal ganz schön cool und funktioniert auch tatsächlich. Der folgende Beispielcode ist einfach eine Erweiterung des Beispiels. Für das angegebene Beispiel ist es nicht einmal unbedingt nötig – doch dazu später mehr. So ein Endpoint könnte also so aussehen:

@Singleton
@ServerEndpoint("/websocket")
public class WebsocketEndpoint {

    @Inject
    private SessionBean sessionBean;

    private static final Logger LOG = Logger.getLogger(WebsocketEndpoint.class.getName());

    private static final Set sessions = Collections.synchronizedSet(new HashSet());

    @OnOpen
    public void onOpen(final Session session) {
        try {
            session.getBasicRemote().sendText("session opened");
            sessions.add(session);

            if (sessionBean == null) {
                LOG.log(Level.INFO, "senderBean is null");
            }
        } catch (IOException ex) {
            LOG.log(Level.SEVERE, null, ex);
        }
    }

    @OnMessage
    public void onMessage(final String message, final Session client) {
        if (sessionBean != null) {
            try {
                client.getBasicRemote().sendText("sending message to SessionBean...");
            } catch (IOException ex) {
                LOG.log(Level.SEVERE, "Error on WebSocket", ex);
            }

            sessionBean.handleMessage(message);
        }
    }

    @OnClose
    public void onClose(final Session session) {
        try {
            session.getBasicRemote().sendText("WebSocket Session closed");
            sessions.remove(session);
        } catch (IOException ex) {
            LOG.log(Level.SEVERE, "Error on close.", ex);
        }
    }

    public void onCDIEvent(@Observes @WsMessage String msg) {
        LOG.log(Level.INFO, "Got Callback at WebSocket!");
        for (Session s : sessions) {
            try {
                s.getBasicRemote().sendText("message from CDI: " + msg);
            } catch (IOException ex) {
                LOG.log(Level.SEVERE, "Can's send Message: ", ex);
            }
        }
    }
}

und die SessionBean dazu:

@Stateless
public class SessionBean {

    private static final Logger LOG = Logger.getLogger(SessionBean.class.getName());

    @Inject
    @WsMessage
    Event cdiEvent;

    @Asynchronous
    public void handleMessage(String message) {
        LOG.log(Level.INFO, "handling message {0}.", message);
        cdiEvent.fire(message);
    }
}

Der Qualifier ist einfach ein Qualifier, den Netbeans selbst generieren kann. Wie man sieht, benutze ich hier keine MDB wie im Beispiel, sondern einfach einen Asynchronen Aufruf. Der Effekt ist aber der gleiche. Wir halten also fest: man kann mit CDI Events von einer EJB ins Frontend Nachrichten schicken! Sehr hübsch!

Ein weiteres Detail, das ins Auge sticht, ist, dass der WebSocket Endpoint gleichzeitig als Singleton annotiert ist. Das darf man laut Doku und war die einzige Möglichkeit, die EJB in den Endpoint hineinzubekommen. Das funktinierte mitunter auch erst nach einem Server Neustart aber immerhin. Ich bin offensichtlich nicht der einzige mit diesem Problem. Eine Singleton EJB ist dann die logische Wahl. Ich speichere dort schließlich alle offenen Verbindungen und möchte deshalb auch immer dieselbe Bean haben. Daraus ergibt sich dann eine weitere Möglichkeit für einen Callback:

Callback in den WebSocket via Singleton Bean

Da der WebSocket Endpint bereits eine EJB ist, kann ich prinzipiell diese injecten und direkt aufrufen. Wer das von der SessionBean aus versucht, wird feststellen, dass der Applicationserver unzufrieden ist: wir haben eine zirkuläre Abhängigkeit, da sich Endpoint und Bean gegenseitig referenzieren. Wenn man aber tatsächlich über eine MDB geht, kann diese dann problemlos den WebSocket Endpoint aufrufen. Die Session Bean sähe dann etwa so aus:

@Stateless
public class SessionBean {

    private static final Logger LOG = Logger.getLogger(SessionBean.class.getName());

    @Resource(mappedName = "jms/myQueue")
    private Queue myQueue;
    @Inject
    private JMSContext jmsContext;

    public void handleMessage(String message) {
        LOG.log(Level.INFO, "handling message {0}.", message);
        jmsContext.createProducer().send(myQueue, "(" + message + ")");
    }
}

und die dazugehörige MDB so:

@MessageDriven(mappedName = "jms/myQueue")
public class MessageBean implements MessageListener {

    private static final Logger LOG = Logger.getLogger(MessageBean.class.getName());

    @Inject
    WebsocketEndpoint endpoint;

    @Override
    public void onMessage(Message message) {
        try {
            // rufe die Eventmethode direkt auf
            endpoint.onCDIEvent(message.getBody(String.class));
        } catch (JMSException ex) {
            LOG.log(Level.SEVERE, "Error extractiong Message.", ex);
        }
    }
}

Ok, ganz prima. Geht. Champagner! Und jetzt denkt sich der unbedarfte Entwickler: „Juhu, jetzt mache ich einfach aus der Queue ein Topic und schon habe ich eine 1a Lösung für den Cluster!“

Nachrichten im Cluster

Wenn man sich überlegt, wie JMS im Glassfish standardmäßig aufgebaut ist, entdeckt man, dass jede Clusterinstanz eine eigene Broker-Instanz mit hochzieht. Üblicherweise landen also die Nachrichten, die von einer Instanz geschickt werden bei dem lokalen Broker und werden auch wieder an die lokale Instanz geschickt. In dem Szenario funktioniert zumindest das Beispiel mit der Queue schon einmal recht wahrscheinlich.

Cluster Instanz
Cluster Instanz

Wenn jetzt allerdings der Broker ausfällt, wird der von der Nachbarinstanz verwendet. Dass die Nachricht wieder bei uns abgeliefert wird, ist unwahrscheinlicher. Bei einer Konfiguration mit einem externen Broker ist es ohnehin zufällig, wo die Nachricht abgeliefert wird. Sie muss ja nur einmal garantiert bei einer angemeldeten MDB ankommen.

Cluster
Cluster

Das ist natürlich irgendwie doof, denn die Clients sind ja jetzt mit einer stehenden Verbindung mit einer Instanz des Clusters physikalisch verbunden. Es gibt also auch keine Möglichkeit, die Verbindungen mal eben zu replizieren. Aber das gilt ja für eine Queue. Wir wollten ja ohnehin ein Topic verwenden und damit dann alle Instanzen befüttern…

Auch hier sind wir nicht die ersten mit der Idee und lesen, dass da bereits schon einmal jemand drüber gestolpert ist. Es ist also zwar spezifiziert, dass ein Topic zu jeder Application – also zu Jeder MDB-Klasse geliefert werden muss, aber nicht zu jeder Instanz dieser Klasse. Da ich auf dem Cluster nur verschiedene Instanzen der selben MDB verteile, reicht es, wenn eine dieser Instanzen die Nachricht erhält. Die Idee eines Clusters ist ja, dass alle Instanzen identisch sind und es demzufolge gleichgültig ist, wer die Arbeit macht. Nur damit funktioniert die Verteilung leider nicht wie gehofft.

Paradigmenwechsel

Die Gleichheit der Cluster Instanzen ist durch das Vorhandensein physikalischer Verbindungen nicht mehr gegeben. Das Bedeuten zum einen, dass bei dem Ausfall einer Instanz aller darauf vorhandenen Verbindungen wegsterben (Stichwort Reconnect im Client) und zum anderen, dass es nicht egal ist, welche Instanz einen Request behandelt. So lange also JMS 2.1 noch nicht da ist, muss man sich selbst behelfen. Das großartige Atmosphere löst schon einmal einen großen Teil dieser Probleme. So kümmert es sich auch um die Verteilung von Nachrichten im Cluster. (Oh, und Primefaces hat übrigens Atmosphere bereits integriert.)

Wenn man interessante Dinge wie Message Routing braucht wie beispielsweise bei einem private Chat, um mal das Lieblingsbeispiel für WebSockets zu strapazieren, bei dem zwei Benutzer direkt miteinander kommunizieren sollen, wird es schon kniffelig. In dem Fall ist ein Broadcast von allen Nachrichten auf alle Clusterinstanzen etwas ineffizient. Da müsste man sich dann überlegen, ob man nicht lieber Referenzen zu allen Instanzen hält und die Nachricht direkt an den Empfänger schickt. Also mehr wie bei einem Switch im Gegensatz zu einem Hub.

Es bleibt also spannend.

Logging hilft!

Auf der Suche nach einem unangenehmen Problem in einem Live System strahlten mich aus der Logdatei einige Stacktraces an, gegen die dieser  wie eine FSK12 Version anmutet. Ein kurzer Blick in den Code zeigte dann etwa dies:

try {
    meinBackend.machTotalVielKompliziertesZeug(meineBestellung);
} catch (Exception e) {
    LOGGER.log(Level.SEVERE, "Ups", e);
}

Und das war in etwa das einzige Log-Statement im Code. Das ist natürlich schon mal besser als nichts – aber auch nicht wirklich viel besser. In einem kleinen, sinnfreien Beispiel sieht das etwa so aus:

Apr 09, 2014 7:10:46 PM logtest.LogTest machDingeDieDannInDerGuiAngezeigtWerden
SCHWERWIEGEND: Ups
java.lang.NullPointerException
	at logtest.LogTest$Backend.machTotalVielKompliziertesZeug(LogTest.java:22)
	at logtest.LogTest.machDingeDieDannInDerGuiAngezeigtWerden(LogTest.java:53)
	at logtest.LogTest.main(LogTest.java:47)

Der Senior Developer guckte mich etwas traurig an, zuckte mit den Schultern und sagte, da müsse man halt reindebuggen.

Ok, mit dem Debugger auf das Produnktivsystem ist selten die beste Idee. Also wird der Produktivstand auf eine Testumgebung gezogen und der Fehler nachgestellt. Moment, „der Fehler Nachgestellt“ mit welchen Parametern überhaupt? Was ist da passiert? Was wurde versucht?

Agile trifft auf BWL

Logging hat in vielen Firmen keine Priorität. Das liegt oft an einem sehr eigenwilligen Scrumm Konstrukt: Der Product Owner ist automatisch Repräsentant des Endkunden. Wenn dieser die Applikation nicht selber betreibt, wird er Logging nicht explizit als Feature fordern, also fließt kein Geld, also ist es nicht relevant. Die Betreiber In House produzieren ohnehin nur Kosten und haben deshalb auch kein Budget für Anforderungen. Ich habe bisher tatsächlich maximal gesehen, dass Logging als Best Practice in einem Code Review mit Priorität so um D-F angeregt wird, jedoch nie, dass es als tatsächliche Anforderung auftaucht. (Vielleicht hat ja jemand da draußen das System geknackt und kann hilfreiche Anregungen bieten, wie sich Betriebsanforderungen in die Requirements mit einem Kostenträger einbinden lassen.)

Bis dahin subsumiere ich Logging mal unter Technical Debt und fordere es als Best Practice ein.

Was Loggen?

Gutes Logging vereinfacht die Fehlersuche. Ein paar strategisch sinnvoll untergebrachte Log Statements lassen einen gleich viel klarer sehen:

public void machDingeDieDannInDerGuiAngezeigtWerden() {
    Bestellung meineBestellung = new Bestellung("42");
    try {
        meinBackend.machTotalVielKompliziertesZeug(meineBestellung);
    } catch (Exception e) {
        LOGGER.log(Level.SEVERE, "Problem beim Dinge machen für die GUI.", e);
    }
}

und in der aufgerufenen Methode dann:

public void machTotalVielKompliziertesZeug(Bestellung bestellung) {
    LOGGER.log(Level.INFO, "mache kompliziertes Zeug mit der Bestellung {0}.", bestellung);

    konfiguration.getConfigFor("live");

    nochVielKomplizierteresZeug();
}

ergibt schon mal

Apr 09, 2014 8:11:39 PM logtest.LogTest$Backend machTotalVielKompliziertesZeug
INFORMATION: mache kompliziertes Zeug mit der Bestellung 42.
Apr 09, 2014 8:11:39 PM logtest.LogTest machDingeDieDannInDerGuiAngezeigtWerden
SCHWERWIEGEND: Problem beim Dinge machen für die GUI.
java.lang.NullPointerException: Konfiguration ist Null.
    at logtest.LogTest$Konfiguration.getConfigFor(LogTest.java:22)
    at logtest.LogTest$Backend.machTotalVielKompliziertesZeug(LogTest.java:34)
    at logtest.LogTest.machDingeDieDannInDerGuiAngezeigtWerden(LogTest.java:70)
    at logtest.LogTest.main(LogTest.java:64)

(Dem aufmerksamen Leser wird nicht entgangen sein, dass sich der Stack Trace ändert, weil ich nach und nach das Beispiel größer mache. Es geht aber auch nicht um den Stacktrace…)
Man könnte jetzt also schon einmal sehen, dass da offensichtlich etwas in der Konfiguration schief gegangen ist bei der Bestellung 42. Der wichtige Aspekt hierbei ist, dass die Bestellung, um die es geht, mit ausgegeben wird. Jetzt wieß man zumindest schon mal worum es geht und kann ggf. in der Datenbank mal fix Nachschlagen. Aber hier handelt es sich scheinbar um ein Konfigurationsproblem. Kümmern wir uns also um die Konfigurationsmethode:

public String getConfigFor(String key) {
    String value = config.get(key);
    if (value == null) {
        value = fallback.get(key);
        if (value == null) {
            LOGGER.log(Level.SEVERE, "Keine Konfiguration für \"{0}\" vorhanden.", key);
            throw new NullPointerException("Konfiguration für \"" + key + "\" ist Null.");
        } else {
            LOGGER.log(Level.WARNING, "Keine Konfiguration für \"{0}\". Benutze Defaulteintrag \"{1}\".", new Object[]{key, value});
        }
    } else {
        LOGGER.log(Level.INFO, "Konfiguration für \"{0}\" ist: \"{1}\"", new Object[]{key, value});
    }
    return value;
}

Damit hätten wir dann etwa folgende Ausgabe:

Apr 09, 2014 9:16:25 PM logtest.LogTest$Konfiguration 
INFORMATION: Lade konfiguration von /var/web/configs/config.cfg
Apr 09, 2014 9:16:25 PM logtest.LogTest$Backend machTotalVielKompliziertesZeug
INFORMATION: mache kompliziertes Zeug mit der Bestellung 42.
Apr 09, 2014 9:16:25 PM logtest.LogTest$Konfiguration getConfigFor
WARNUNG: Keine Konfiguration für "DB". Benutze Defaulteintrag "localhost:1234".
Apr 09, 2014 9:16:25 PM logtest.LogTest$Konfiguration getConfigFor
INFORMATION: Konfiguration für "Cachefolder" ist: "/var/webservers/globalcahe"
Apr 09, 2014 9:16:25 PM logtest.LogTest$Konfiguration getConfigFor
WARNUNG: Keine Konfiguration für "live" vorhanden.
Apr 09, 2014 9:16:25 PM logtest.LogTest machDingeDieDannInDerGuiAngezeigtWerden
SCHWERWIEGEND: Problem beim Dinge machen für die GUI.
java.lang.NullPointerException: Konfiguration für "live" ist Null.
    	at logtest.LogTest$Konfiguration.getConfigFor(LogTest.java:40)
	    at logtest.LogTest$Backend.machTotalVielKompliziertesZeug(LogTest.java:60)
	    at logtest.LogTest.machDingeDieDannInDerGuiAngezeigtWerden(LogTest.java:96)
	    at logtest.LogTest.main(LogTest.java:90)

Mit einer derartigen Ausgabe könnte vermutlich bereits der Administrator etwas anfangen und das Problem würde gar nicht erst bis in die Entwicklungsabteilung durchgereicht. Ihm würde vermutlich auch gleich noch auffallen, dass die DB Verbindung als Fallback localhost nimmt, was vermutlich nur auf dem Rechner des Entwicklers zu dem gewünschten Ergebnis führt.

Es ist also durchaus hilfreich, wenn auch jemand ohne der Quellcode sehen kann, was in der Anwendung vorgeht. Wichtig ist vor allem, dass nicht nur ausgegeben wird, was getan wird, sondern vor allem auch womit etwas getan wird.

Jetzt kommen hoffentlich die Einwände „Aber Level Info möchte ich im Produktivsystem doch gar nicht sehen!“…

Wie viel loggen?

Richtig. INFO will man in einem Produktivsystem gar nicht sehen. An sich möchte man im laufenden Betrieb gar nichts sehen, so lange es keine Probleme gibt. Sprich, eine Anwendung sollte Log-Clean sein. Am Ende des Tages schreibt ein log irgendwo hin und das kostet Zeit und ist im Fall des Filesystems nicht parallelisierbar. Deswegen ist es wichtig, dass die Log Level dynamisch angehoben werden können. Es muss möglich sein, ohne durchstarten des Systems den Loglevel auf einem Cluster Node mal kurzfristig auf INFO zu setzen, damit man ohne einen Debugger Probleme im Betrieb finden kann.

Nun ist es dafür meist zu spät, wenn das Kind bereits in den Brunnen gefallen ist und Fehler auf der schwerwiegendsten Stufe produziert hat. Dafür gibt es eine total brillante Erfindung:  den Memory Logger. Hier werden, ähnlich, wie bei einem Flugschreiber, die Logs in einen Buffer geschrieben, der eine Anzahl von Einträgen zwischenspeichert und auf Kommando (meist das Auftreten einen schwerwiegenden Logmeldung) in das Log schreibt. Man sieht also im Fehlerfall eine begrenzte Zahl von INFO ausgaben, die dem Fehler direkt vorausgehen. Das ist enorm praktisch. J.U.L. hat den bereits standardmäßig dabei, für log4j muss man ihn laden oder schreiben und ähnliches gilt für logback.

Wie loggen?

Wie man in dem Beispielcode sieht, ist die API von J.U.L. nicht gerade sehr ansprechend. Weiterhin ist es bei Applicationservern hilfreich, den Logger des Applicationservers zu verwenden, da der mitunter spannende Dinge macht wie Filterung auf Anwendungsbasis. Von daher würde ich im produktiven Umfeld immer zu SLF4J greifen. Es hat den Vorteil, dass es beliebige Backends mit einer API bedient und die ist auch noch sehr angenehm zu benutzen.

Weiterhin sollte Logging so einfach wie möglich sein. Es ist das, was immer funktionieren muss. Loggen in eine Datei ist einfach und genau deshalb auch der Standard für jede Form von Appserver. Ich habe auch schon Log Appender gesehen, die hintenrum eine EJB bedienen, die dann über JMS Logs verteilt. Es hat zwar bestimmt Spaß gemacht, das zu entwickeln, widerspricht aber der grundlegenden Anforderung der Einfachheit. Mal ganz zu schweigen davon, dass das Logging in der Initialisierunsphase des Appservers ganz einfach nicht funktioniert.

Ich habe auch schon gesehen, dass in einem Cluster das Logging sämtlicher Nodes in ein NFS Share laufen. Die Idee daran war, eine zentrale Stelle zu haben, an der man die Logs einsehen kann. Das hat allerdings den Nachteil, neben der Preformanceproblematik eines NFS, dass der Komplette Cluster steht wenn das NFS nicht tut. Wenn man Logs aggregieren möchte, gibt es dafür prima Tools, die Logs von allen Systemen zusammensammeln und zentral verfügbar machen ohne die Funktionalität des Clusters zu beeinträchtigen.

Schreibt Logs!