NPE in ServerImpl reading from no sync input stream

[viretp]

We have a proxy using robaho httpserver (1.0.22). It starts two http servers: the one for the proxy, and one for prometheus scraping endpoint. The server used for prometheus catches a NullPointerException and logs only its name, not it's content and stacktrace, even when we set the log level to FINEST.
We see following output in log:

2025-04-02 07:50:11.995 FINER pool-1-thread-1 robaho.net.httpserver.ServerImpl$Exchange run [http:9999] exchange started [9999.43162]
2025-04-02 07:50:11.995 FINER pool-1-thread-1 robaho.net.httpserver.ServerImpl$Exchange runPerRequest [http:9999] reading request
2025-04-02 07:50:11.995 WARNING pool-1-thread-1 robaho.net.httpserver.ServerImpl$Exchange run [http:9999] ServerImpl unexpected exception
java.lang.NullPointerException
2025-04-02 07:50:11.995 FINER pool-1-thread-1 robaho.net.httpserver.ServerImpl closeConnection [http:9999] closing connection: [9999.43162]

We suppose that the NPE is caused by some network or resource problem.
The same block appears very oft during some time (maybe during 3 seconds or during 15 seconds) when the proxy has actually not even requests to serve, so the JVM has seemingly nothing to do. The same 5 lines are logged like in a loop, 20k times in 3 seconds (!), then no more. During this time, prometheus cannot access the scrape end point. But afterwards it runs smoothly, without a restart...

Is it possible to log more information in case an unexpected exception occurs? In code, the exception is actually logged but strangely we only see the exception class name, nothing more: this is strange, as we use the java util logging and there an exception is typically logged with message and stack trace. Or do you have an idea what occurs with the logging ?

[robaho]

Have you tried disabling omit stacktrace in throw?

See https://yoshihisaonoue.wordpress.com/2021/02/07/jvm-option-xx-omitstacktraceinfastthrow/

And please report back.

You can also run it under the debugger and break on exception to capture.

Typically this is caused when the system is rapidly looping throwing exceptions - which can happen when the exception logging is actually throwing an exception. Do you have a custom logger installed?

Still, I would expect the very first exception to be logged. You might need to increase your log file rollover sized.

[nikosf95]

can i work on this?please assign

[robaho]

can i work on this?please assign

Sure. I certainly accept PRs. I suspect though that the problem lies in the application level code not the ServerImpl - but not saying the logging couldn’t be improved too.

If your changes are substantial you should run the design by me first. Thanks.

[nikosf95]

ok @robaho, could you please assign this to me to start working?

[nikosf95]

@robaho , can you please give me rights so i can push my branch?

[viretp]

Thank you for your advice concerning omit stack trace option: you were right, we could find the stack trace in the first occurrences of the exception:

2025-04-02 07:50:10.904 FINER pool-1-thread-1 robaho.net.httpserver.ServerImpl$Exchange run [http:9999] exchange started [9999.47694]
2025-04-02 07:50:10.904 FINER pool-1-thread-1 robaho.net.httpserver.ServerImpl$Exchange runPerRequest [http:9999] reading request
2025-04-02 07:50:10.904 WARNING pool-1-thread-1 robaho.net.httpserver.ServerImpl$Exchange run [http:9999] ServerImpl unexpected exception
java.lang.NullPointerException: Cannot read the array length because "<parameter1>" is null
at java.base/java.io.FilterInputStream.read(Unknown Source)
at robaho.net.httpserver.NoSyncBufferedInputStream.fill(Unknown Source)
at robaho.net.httpserver.NoSyncBufferedInputStream.read(Unknown Source)
at robaho.net.httpserver.Request.readLine(Unknown Source)
at robaho.net.httpserver.Request.readRequestLine(Unknown Source)
at robaho.net.httpserver.Request.<init>(Unknown Source)
at robaho.net.httpserver.ServerImpl$Exchange.runPerRequest(Unknown Source)
at robaho.net.httpserver.ServerImpl$Exchange.run(Unknown Source)
at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(Unknown Source)
at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(Unknown Source)
at java.base/java.lang.Thread.run(Unknown Source)
2025-04-02 07:50:10.904 FINER pool-1-thread-1 robaho.net.httpserver.ServerImpl closeConnection [http:9999] closing connection: [9999.47694]

The problem is not easy to reproduce in a debugger as it only occurs after several days on our system, and only for a relative short time (3 to 20 seconds).

[viretp]

Maybe in robaho.net.httpserver.NoSyncBufferedInputStream.fill method a null check of the field "buf" is missing ?

[robaho]

Can you reproduce with the line number information included?

It feels like you might be using background threads that are concurrently reading from the input stream without proper synchronization.

[robaho]

Are you by chance using a background thread in the handler itself? This is supported but you have to know what you are doing. The server is designed with a thread per request model and optimized for this case - normally addressed using virtual threads.

[viretp]

The error occurs in the case of our prometheus end point. Hier what we do with this http server:

• the server is bound to a port
• the context "/prometheus" is added
• each time we get a request, we get the statistics out of Micrometer and send them as response

That's all. We do nothing with a separate thread. But we have another httpserver running in the same JVM serving the real end point of our application.

    public void init(final String hostname, final int port, final boolean accessLogDisabled) {
        LOG.log(Level.FINEST, "init({0}, {1})", new Object[] { hostname, port });
        enabled = true;
        PrometheusMeterRegistry prometheusMeterRegistry = new PrometheusMeterRegistry(PrometheusConfig.DEFAULT);
        registry.add(prometheusMeterRegistry);
        if (accessLogDisabled) {
            accessLog = null;
        } else {
            accessLog = new AccessLog(Collections.emptyList());
        }
        try {
            httpServer = HttpServer.create();
            if ("*".equals(hostname)) {
                httpServer.bind(new InetSocketAddress(port), 0);
            } else {
                httpServer.bind(new InetSocketAddress(InetAddress.getByName(hostname), port), 0);
            }
            httpServer.createContext("/prometheus", httpExchange -> {
                long millis = System.currentTimeMillis();
                int responseLength = -1;
                try {
                    String response = prometheusMeterRegistry.scrape();
                    responseLength = response.getBytes().length;
                    httpExchange.sendResponseHeaders(200, responseLength);
                    try (
                            OutputStream os = httpExchange.getResponseBody()) {
                        os.write(response.getBytes());
                    }
                } catch (Exception e) {
                    LOG.log(Level.SEVERE, "Error during prometheus scraping", e);
                    httpExchange.sendResponseHeaders(500, -1);
                } finally {
                    httpExchange.close();
                    if (accessLog != null) {
                        accessLog.log(httpExchange, responseLength, "-", System.currentTimeMillis() - millis, System.currentTimeMillis() - millis);
                    }
                }
            });
            httpServer.setExecutor(Executors.newSingleThreadExecutor());
            httpServer.start();
            LOG.log(Level.INFO, "Prometheus scrape endpoint listening on http://{0}:{1}/prometheus", new Object[] { hostname, port });
        } catch (IOException e) {
            throw new RuntimeException(e);
        }
    }

[viretp]

Can you reproduce with the line number information included?

It feels like you might be using background threads that are concurrently reading from the input stream without proper synchronization.

I have checked the class NoSyncBufferedInputStream and the NPE must be produced on line 86 (version 1.0.22): the FilterInputStream.read throws NPE if buf is null.

    private void fill() throws IOException {
        pos = 0;
        count = 0;
        int n = getInIfOpen().read(buf);
        if (n > 0)
            count = n;
    }