JSSE Debug Log redirection

[Bernd]

Hello,

since the backport of the new TLS 1.3 capable JSSE provider the debug
logging of JSSE has changed. This is due to the usage of unified logging,
which is not available on Java 8.

There are some hints in the backport ticket (16 New Debug Logger):

https://bugs.openjdk.java.net/browse/JDK-8248721

- in versions before the backport I could specify -Djavax.net.debug=all to
turn on internal debug logging.
- This was sent to stdout and it DID honor System.setOut() redirection.

This especially means on an application server like JBoss the output is
redirected to the (rolling) application server main logfile, but in the
last two quarterly updates, this is no longer the case.

This looks like a regression to me, the new internal debug loggers used by
JSSE should still write to System.out (and honor redirect)

However, I see that the new JUL logger (and in future the platform logger)
have their benefit, so suppose I want to make changes to my existing code
to accommodate this, how can I actually access and redirect those log
messages? According to the backport request there is some difference
between requesting a JUL logger or creating a internal one dependning on
the value of the system propery.

So I tried to register a handler to see if I can catch those log messages,
but I have not. It works for some messages like the Debug from
X509Certificate, but it does not work for the handshake stuff:

(in the following console output "JUL " is from my handler and
"java.net.ssl|..." is from the internal handling, it will not honor
System.setOut redirects, either.)

java version "1.8.0_261"
Java(TM) SE Runtime Environment (build 1.8.0_261-b12)
Java HotSpot(TM) 64-Bit Server VM (build 25.261-b12, mixed mode)

JUL FINE|1604441741129 started
JUL FINE|1604441741129 ssl started
JUL FINE|1604441741129 ssl started
Connect to https://www.google.com ...
*javax.net.ssl*|FINE|01|main|2020-11-03 23:15:41.270 CET|
*SSLContextImpl.java*:425|System property jdk.tls.client.cipherSuites is
set to 'null'
javax.net.ssl|FINE|01|main|2020-11-03 23:15:41.275
CET|SSLContextImpl.java:425|System property jdk.tls.server.cipherSuites is
set to 'null'
*JUL FINE*|1604441741327 *X509Certificate*: Alg:{0}, Serial:{1},
Subject:{2}, Issuer:{3}, Key type:{4}, Length:{5}, Cert Id:{6}, Valid
from:{7}, Valid until:{8}
JUL FINE|1604441741328 X509Certificate: Alg:{0}, Serial:{1}, Subject:{2},
Issuer:{3}, Key type:{4}, Length:{5}, Cert Id:{6}, Valid from:{7}, Valid
until:{8}
...
javax.net.ssl|FINE|01|main|2020-11-03 23:15:42.358
CET|Finished.java:522|Consuming server Finished handshake message (
"Finished": {
  "verify data": {
    0000: 46 40 BF 48 6E 83 A9 7F   6A E0 5A 4D
  }'}
)
JUL FINE|1604441742359  TLSHandshake: {0}:{1}, {2}, {3}, {4}
Using TLS_ECDHE_ECDSA_WITH_AES_128_GCM_SHA256
-- iterates registered loggers:
log javax.net.ssl null
log sun.net.www.protocol.http.HttpURLConnection null
log jdk.event.security null
log global null
log  ALL
JUL close
JUL close

...
I get the same output with -Djava.net.debug=all and -Djava.net.debug. Looks
like the SSLContextImpl or Dinished.java is always using its own logger
with no way to register an handler?

Gruss
Bernd

PS: the sample code is here:

/* SPDX-License-Identifier: apache-2.0 */
package net.eckenfels.test.ssl;

import java.io.File;
import java.io.FileOutputStream;
import java.io.IOException;
import java.io.PrintStream;
import java.net.HttpURLConnection;
import java.net.URL;
import java.util.Enumeration;
import java.util.logging.Handler;
import java.util.logging.Level;
import java.util.logging.LogManager;
import java.util.logging.LogRecord;
import java.util.logging.Logger;

import javax.net.ssl.HttpsURLConnection;

import net.eckenfels.test.ssl.UrlInspect.MyHandler;

public class UrlInspect
{
    public static class MyHandler extends Handler
    {
        @Override
        public void publish(LogRecord record) {
            System.out.println("JUL " + record.getLevel() + "|" +
record.getMillis() + " " + record.getMessage());
        }

        @Override
        public void flush()  {
            System.out.println("JUL flush");
            System.out.flush();
        }

        @Override
        public void close() throws SecurityException {
            System.out.println("JUL close");
        }
    }

    public static void main(String[] args) throws IOException {
        Handler mh = new MyHandler();
        LogManager.getLogManager().reset();
        Logger root = LogManager.getLogManager().getLogger("");
        root.setLevel(Level.ALL);
        root.addHandler(mh);

        Logger log = Logger.getLogger("javax.net.ssl");
        log.addHandler(mh); // not needed

        root.fine("started");
        log.fine("ssl started");

        //FileOutputStream log = new FileOutputStream(new File("out.log"));
        //System.setOut(new PrintStream(log));

//sun.util.logging.PlatformLogger.getLogger("sun.net.www.protocol.http.HttpsURLConnection")
.setLevel(Level.ALL);

        URL url = new URL((args.length < 1)?"https://developer.google.com
":args[0]);
        System.out.println("Connect to " + url + " ...");

        HttpURLConnection.setFollowRedirects(false);
        HttpsURLConnection c = (HttpsURLConnection)url.openConnection();
        c.connect(); // throws SSL handshake exception
        System.out.println("Using " + c.getCipherSuite());

        System.out.println("-- iterate registered loggers");
        Enumeration<String> e = LogManager.getLogManager().getLoggerNames();
        while(e.hasMoreElements())
        {
            String n = e.nextElement();
            System.out.println("log " + n + " " +
Logger.getLogger(n).getLevel());
        }
    }
}
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <https://mail.openjdk.org/pipermail/security-dev/attachments/20201103/4989224b/attachment.htm>