Errors deleting multipart tmp files java.lang.NullPointerException under heavy load

[behrangsa]

Jetty version

9.4.24.v20191120

Java version

AdoptOpenJDK 11.0.5 HotSpot

OS type/version

Linux, Ubuntu 19.04

Description

Under mostly file-upload heavy load, Jetty sometimes throws an NPE:

2019-12-01 16:43:02.283:WARN:oejshC.file_server:qtp1992550266-93: Errors deleting multipart tmp files
java.lang.NullPointerException
	at org.eclipse.jetty.http.MultiPartFormInputStream.deleteParts(MultiPartFormInputStream.java:401)
	at org.eclipse.jetty.server.MultiParts$MultiPartsHttpParser.close(MultiParts.java:79)
	at org.eclipse.jetty.server.MultiPartCleanerListener.requestDestroyed(MultiPartCleanerListener.java:48)
	at org.eclipse.jetty.server.handler.ContextHandler.requestDestroyed(ContextHandler.java:1263)
	at org.eclipse.jetty.server.handler.ContextHandler.doHandle(ContextHandler.java:1302)
	at org.eclipse.jetty.server.handler.ScopedHandler.nextScope(ScopedHandler.java:188)
	at org.eclipse.jetty.servlet.ServletHandler.doScope(ServletHandler.java:485)
	at org.eclipse.jetty.server.session.SessionHandler.doScope(SessionHandler.java:1577)
	at org.eclipse.jetty.server.handler.ScopedHandler.nextScope(ScopedHandler.java:186)
	at org.eclipse.jetty.server.handler.ContextHandler.doScope(ContextHandler.java:1212)
	at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:141)
	at org.eclipse.jetty.server.handler.ContextHandlerCollection.handle(ContextHandlerCollection.java:221)
	at org.eclipse.jetty.server.handler.HandlerCollection.handle(HandlerCollection.java:146)
	at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:127)
	at org.eclipse.jetty.server.Server.handle(Server.java:500)
	at org.eclipse.jetty.server.HttpChannel.lambda$handle$1(HttpChannel.java:383)
	at org.eclipse.jetty.server.HttpChannel.dispatch(HttpChannel.java:547)
	at org.eclipse.jetty.server.HttpChannel.handle(HttpChannel.java:375)
	at org.eclipse.jetty.server.HttpConnection.onFillable(HttpConnection.java:270)
	at org.eclipse.jetty.io.AbstractConnection$ReadCallback.succeeded(AbstractConnection.java:311)
	at org.eclipse.jetty.io.FillInterest.fillable(FillInterest.java:103)
	at org.eclipse.jetty.io.ChannelEndPoint$2.run(ChannelEndPoint.java:117)
	at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.runTask(EatWhatYouKill.java:336)
	at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.doProduce(EatWhatYouKill.java:313)
	at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.tryProduce(EatWhatYouKill.java:171)
	at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.run(EatWhatYouKill.java:129)
	at org.eclipse.jetty.util.thread.ReservedThreadExecutor$ReservedThread.run(ReservedThreadExecutor.java:388)
	at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:806)
	at org.eclipse.jetty.util.thread.QueuedThreadPool$Runner.run(QueuedThreadPool.java:938)
	at java.base/java.lang.Thread.run(Thread.java:834)

** How to reproduce **

You can run the Gatling load tests in this project: https://github.com/turingg/file-server/tree/jetty-npe (the jetty-npe tag).

[olamy]

what is the jetty version you are using?

[behrangsa]

It's mentioned in the bug report.

…

On Sun, 1 Dec. 2019, 6:10 pm Olivier Lamy, ***@***.***> wrote: what is the jetty version you are using? — You are receiving this because you authored the thread. Reply to this email directly, view it on GitHub <#4383>, or unsubscribe <https://github.com/notifications/unsubscribe-auth/AAAEQE3QLQ3HW7A3IFV3BRLQWNPQBANCNFSM4JTKHAUA> .

[behrangsa]

Seems to be an issue with async servlets.

This servlet won't cause that error:

@WebServlet(name = "SyncUploadServlet", urlPatterns = "/sync/upload")
@MultipartConfig
public class SyncUploadServlet extends AbstractUploadServlet {

    @Override
    protected void doPost(HttpServletRequest request, HttpServletResponse response) {
        try {
            doPostImpl(request, response);
        } catch (Exception e) {
            doQuietly(() -> {
                response.setStatus(SC_INTERNAL_SERVER_ERROR);
                response.getWriter().println("Failure");
                response.getWriter().flush();
                response.getWriter().close();
            });

            return;
        }

        doQuietly(() -> {
            response.setStatus(SC_OK);
            response.getWriter().println("Success");
            response.getWriter().flush();
            response.getWriter().close();
        });
    }

    private void doPostImpl(HttpServletRequest request, HttpServletResponse response) throws IOException, ServletException {
        if (!isContentTypeValid(request)) {
            sendCustomError(request, response, SC_BAD_REQUEST, "Request is not multipart/form-data.");
            return;
        }

        if (!isDocumentPartValid(request)) {
            sendCustomError(request, response, SC_BAD_REQUEST, "Document part is not valid.");
            return;
        }

        final var documentMetadata = getDocumentMetadata(request);

        if (!isDocumentMetadataValid(documentMetadata)) {
            sendCustomError(request, response, SC_BAD_REQUEST, "Document metadata is not valid.");
            return;
        }

        final var part = request.getPart(DOCUMENT_PART_NAME);

        try {
            saveDocument(documentMetadata, part);
        } catch (IOException | SQLException e) {
            e.printStackTrace();
            sendCustomError(request, response, SC_INTERNAL_SERVER_ERROR, e.getMessage());
        }
    }

    private void saveDocument(final Map<String, String[]> metadata, final Part document) throws IOException, SQLException {
        final var fileName = UUID.randomUUID().toString();
        document.write(fileName);
    }
}

but this one does:

@WebServlet(name = "AsyncUploadServlet", urlPatterns = "/async/upload", asyncSupported = true)
@MultipartConfig
public class AsyncUploadServlet extends AbstractUploadServlet {

    @Override
    protected void doPost(HttpServletRequest request, HttpServletResponse response) {
        final var asyncContext = request.startAsync();
        asyncContext.setTimeout(60_000 * 30);
        asyncContext.start(() -> {
            try {
                if (!isContentTypeValid(request)) {
                    sendCustomError(request, response, SC_BAD_REQUEST, "Request is not multipart/form-data.");
                    return;
                }

                if (!isDocumentPartValid(request)) {
                    sendCustomError(request, response, SC_BAD_REQUEST, "Document part is not valid.");
                    return;
                }

                final var documentMetadata = getDocumentMetadata(request);

                if (!isDocumentMetadataValid(documentMetadata)) {
                    sendCustomError(request, response, SC_BAD_REQUEST, "Document metadata is not valid.");
                    return;
                }

                final var part = request.getPart(DOCUMENT_PART_NAME);

                try {
                    saveDocument(documentMetadata, part);
                } catch (IOException | SQLException e) {
                    e.printStackTrace();
                    sendCustomError(request, response, SC_INTERNAL_SERVER_ERROR, e.getMessage());
                    return;
                }

                response.setStatus(SC_OK);
                response.getWriter().println("Success");
                response.getWriter().flush();
                response.getWriter().close();
            } catch (IOException | ServletException e) {
                e.printStackTrace();
            } finally {
                asyncContext.complete();
            }
        });
    }

    private void saveDocument(final Map<String, String[]> metadata, final Part document) throws IOException, SQLException {
        final var fileName = UUID.randomUUID().toString();
        document.write(fileName);
    }
}

Again, the full source code is available here: https://github.com/turingg/file-server/tree/jetty-npe.

[janbartel]

@lachlan-roberts it could be that the changes you did in jetty-10 for #4368 would mean this doesn't happen in jetty-10 - can you confirm that?

[janbartel]

@behrangsa as a work around, try calling request.getParameter(String) or request.getParameterMap() BEFORE starting async - this will ensure that your multipart content is already parsed and not in some race condition with the request timing out.

[behrangsa]

Hi Jan, I will try that tomorrow but would this race condition get fixed in an upcoming 9.x release by any chance? Best regards, { "blog" : "https://blog.behrang.org", "twitter" : "https://twitter.com/behrangsa", "github" : "https://github.com/behrangsa/", "stackoverflow" : "https://stackoverflow.com/users/309683?tab=profile"}

…

On Tue, Dec 3, 2019 at 1:39 PM Jan Bartel ***@***.***> wrote: @behrangsa <https://github.com/behrangsa> as a work around, try calling request.getParameter(String) or request.getParameterMap() BEFORE starting async - this will ensure that your multipart content is already parsed and not in some race condition with the request timing out. — You are receiving this because you were mentioned. Reply to this email directly, view it on GitHub <#4383>, or unsubscribe <https://github.com/notifications/unsubscribe-auth/AAAEQE3HWFTDDMWIP44U24DQWXBGTANCNFSM4JTKHAUA> .

[lachlan-roberts]

A simple fix was added in 9.4.26 to avoid the NPE (#4479).
A more substantial fix using synchronization has been merged to jetty-10.0.x (#4498) which also ensures the parts are always cleaned up properly when parsing the multipart form asynchronously.