Ako logovať správy SOAPu v Metre?

Mnohokrát chceme vidieť, aké správy odchádzajú z metrového klienta (nie toho, čo má meter, ale klienta v Glassfish Metro) a čo posiela server. Užitočné je to v prípade, že správa síce zo servera dolezie, ale nedá sa spracovať, napríklad kvôli nesprávnemu formátu, či porušeniu politík WS-Security.

Klasický spôsob

Klasický spôsob odporúča pri štarte klienta nastaviť systémovú premennú:

com.sun.xml.ws.transport.http.client.HttpTransportPipe.dump=true

V prípade spúšťania z komandlajny teda

-Dcom.sun.xml.ws.transport.http.client.HttpTransportPipe.dump=true

Klient začne logovať do štandardného výstupu požiadavky v tvare:

---[HTTP request - http://www.webservicex.net/stockquote.asmx]---
Accept: text/xml, multipart/related
Content-Type: text/xml; charset=utf-8
SOAPAction: "http://www.webserviceX.NET/GetQuote"
User-Agent: Metro/2.3 (tags/2.3-7528; 2013-04-29T19:34:10+0000) JAXWS-RI/2.2.8 JAXWS/2.2 svn-revision#unknown
<?xml version='1.0' encoding='UTF-8'?><S:Envelope xmlns:S="http://schemas.xmlsoap.org/soap/envelope/"><S:Body><GetQuote xmlns="http://www.webserviceX.NET/"><symbol>USD</symbol></GetQuote></S:Body></S:Envelope>--------------------

Odpovede budú zase v tvare:

---[HTTP response - http://www.webservicex.net/stockquote.asmx - 200]---
null: HTTP/1.1 200 OK
Cache-Control: private, max-age=0
Content-Length: 992
Content-Type: text/xml; charset=utf-8
Date: Sat, 09 May 2015 16:12:43 GMT
Server: Microsoft-IIS/7.0
X-AspNet-Version: 4.0.30319
X-Powered-By: ASP.NET
<?xml version="1.0" encoding="utf-8"?><soap:Envelope xmlns:soap="http://schemas.xmlsoap.org/soap/envelope/" xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance" xmlns:xsd="http://www.w3.org/2001/XMLSchema"><soap:Body><GetQuoteResponse xmlns="http://www.webserviceX.NET/"><GetQuoteResult>&lt;StockQuotes&gt;&lt;Stock&gt;&lt;Symbol&gt;USD&lt;/Symbol&gt;&lt;Last&gt;90.89&lt;/Last&gt;&lt;Date&gt;5/8/2015&lt;/Date&gt;&lt;Time&gt;4:00pm&lt;/Time&gt;&lt;Change&gt;+1.99&lt;/Change&gt;&lt;Open&gt;90.09&lt;/Open&gt;&lt;High&gt;90.98&lt;/High&gt;&lt;Low&gt;89.49&lt;/Low&gt;&lt;Volume&gt;2646&lt;/Volume&gt;&lt;MktCap&gt;N/A&lt;/MktCap&gt;&lt;PreviousClose&gt;88.90&lt;/PreviousClose&gt;&lt;PercentageChange&gt;+2.24%&lt;/PercentageChange&gt;&lt;AnnRange&gt;57.32 - 101.36&lt;/AnnRange&gt;&lt;Earns&gt;N/A&lt;/Earns&gt;&lt;P-E&gt;N/A&lt;/P-E&gt;&lt;Name&gt;ProShares Ultra Semiconductors&lt;/Name&gt;&lt;/Stock&gt;&lt;/StockQuotes&gt;</GetQuoteResult></GetQuoteResponse></soap:Body></soap:Envelope>--------------------

To všetko je pekné, ale čo so webservermi?

Čo s webservermi?

Logovanie do stdoutu je v Jave staré, divné, neflexibilné, proste no-no. (A nechcete mať catalina.out plný takýchto krásot.)

RóMETRO a JULia

Našťastie Metro v nových verziách potajme loguje aj do java.util.logging loggera. (Kto neverí, nech do zdrojáku beží.) Tento logger je tradične nazvaný názvom triedy, teda com.sun.xml.ws.transport.http.client.HttpTransportPipe.

Presmerovanie do SLF4J

JUL logger je super, ale divne sa konfiguruje (lebo properties), a vôbec, štandard je SLF4j. Našťastie existuje môstik, ktorý preloží logovacie udalosti z JULu do SLF4ja, ktorý ich prepošle do Logbacku.

Závislosti

Závislosti zrejme obsahujú tradičné Metro:

<dependency>
    <groupId>org.glassfish.metro</groupId>
    <artifactId>webservices-rt</artifactId>
    <version>2.3</version>
</dependency>

Logovací môstik má závislosť:

<dependency>
    <groupId>org.slf4j</groupId>
    <artifactId>jul-to-slf4j</artifactId>
    <version>1.7.11</version>
</dependency>
<dependency>
    <groupId>ch.qos.logback</groupId>
    <artifactId>logback-classic</artifactId>
    <version>1.1.3</version>
</dependency>

Konfigurácia logbacku

Logback potom nakonfigurujeme cez logback.xml. Veľmi dôležité je nastaviť LevelChangePropagator, ktorý má dva účely:

zrýchľuje preklad z JUL do SLF4j. Za normálnych okolností totiž SLF4J vytvorí pre každý záznam z JULu záznam do SLF4J a to i pre tie záznamy, ktoré majú vypnuté logovanie, čo môže mať strašidelný výkonnostný dopad.
umožňuje nastavovať levely logovania pre JUL. Bez tejto možnosti totiž zmeny levelov loggerov v logback.xml nebudú mať dopad na ich protipóly v JULe, čo znamená, že žiadne logovanie z Metra sa nebude konať.

Vzorový logback.xml:

<configuration>
    <contextListener class="ch.qos.logback.classic.jul.LevelChangePropagator">
        <resetJUL>true</resetJUL>
    </contextListener>

    <appender name="STDOUT" class="ch.qos.logback.core.ConsoleAppender">
        <encoder>
            <pattern>%logger - %msg%n</pattern>
        </encoder>
    </appender>

    <root level="INFO">
        <appender-ref ref="STDOUT" />
    </root>

    <logger name="com.sun.xml.ws.transport.http.client.HttpTransportPipe" level="TRACE" />
</configuration>

Nastavili sme, okrem iného, logger pre HTTP transportnú rúru, a jej level na TRACE, ktorý zodpovedá JULáckemu levelu FINER použitému v zdrojákoch HttpTransportPipe.

Nastavenie projektu

Na nastavenie projektu potrebujeme v kóde programovo nainštalovať môstik.

SLF4JBridgeHandler.removeHandlersForRootLogger();
SLF4JBridgeHandler.install();

To by za normálnych okolností stačilo, ale celá mašinéria sa spustí až s prvou hláškou do poriadneho SLF4J loggera, čo vykonáme volaním cvičného loggera:

public class MetroTest {
    public static final Logger logger = LoggerFactory.getLogger(MetroTest.class);

    public static void main(String[] args) {

        SLF4JBridgeHandler.removeHandlersForRootLogger();
        SLF4JBridgeHandler.install();

        logger.info("JUL->SLF4J Bridge initialized");

        StockQuote stockQuote = new StockQuote();
        StockQuoteSoap port = stockQuote.getStockQuoteSoap();
        String usd = port.getQuote("USD");
        System.out.println(usd);
    }
}

Spustenie

Aplikácia beží a môžeme sa z nej tešiť!

Demo na GitHube

Demo je na GitHube v repe novotnyr/metro-soap-message-logging-demo.

Róbert Novotný

public static void blog()

Metro a logovanie SOAP správ v HTTP