Wildfly 13 - File Upload Leak (Undertow)

[lucasbasquerotto]

I migrated recently from JBossAS 7.1.1 (Java 7) to Wildfly 13 (Java 8).

Almost everything was fine, but, before 2 days running, the server stopped working with a lot of errors of "Too many open files".

I've never received that before (that I remember).

Restarting the server solved the issue for the moment, but I wanted to know what caused that.

I digged around a bit and found that the docker container in which it was running allowed until 4096 open files, so, for now, I increased this limit in the wildfly container.

This error is not happening anymore, because I increased the limit a lot, but I created a cronjob to verify the top 10 processes that has more opened file descriptors.

Right after restarting, Wildfly have about 600, but, as time goes on, it increases, and sometimes decreases, but when comparing the results of a day with the day before, it increased by about 1000 opened file descriptors.

This is an example of the results after Wildfly was running for 5 days:

pid =  9570 with 6035 fds: java

pid =  8766 with  241 fds: node

pid =  8568 with  235 fds: mysqld

pid =  9058 with   89 fds: java

pid =  2033 with   59 fds: dockerd

pid =  9100 with   34 fds: docker-proxy

pid =  1953 with   22 fds: fail2ban-server

pid =  5303 with   21 fds: httpd

pid =  5270 with   21 fds: httpd

pid =  5212 with   21 fds: httpd

The java process related to wildfly has 6035 opened file descriptors, and this was a moment with very few online users (the other java process is logstash).

I've run the command ls -l /proc/9570/fd to see the opened file descriptor and saw 6045 lines, of which 5312 are similar to the following:

lr-x------ 1 1000 1000 64 Sep 27 03:20 999 -> /opt/jboss/wildfly/standalone/tmp/app.war/undertow6144806476267093537upload (deleted)

So I think there is some leak in the file upload process (although I don't receive errors).

Maybe this is related to this bug in Undertow [UNDERTOW-961] File descriptors leak in MultiPartParserDefinition - JBoss Issue Tracker (created at 19/Jan/17 7:36 AM and resolved at 16/Feb/17 6:02 PM), but I'm not sure (and the issue was solved, although I don't know which version of Undertow Wildfly 13 uses).

I don't remember receiving such issues in JBossAS 7.1.1 (or maybe there was, but in less intensity, in such a way that the service was always restarted before the number of opened file descriptors reached the limit).

I haven't changed the file upload process after the migration, and like I said, I don't receive error during file upload.

Actually, I started receiving about 5 or 10 errors per day like:

java.io.IOException: UT000128: Remote peer closed connection before all data could be read

at io.undertow.conduits.FixedLengthStreamSourceConduit.exitRead(FixedLengthStreamSourceConduit.java:338)

at io.undertow.conduits.FixedLengthStreamSourceConduit.read(FixedLengthStreamSourceConduit.java:255)

at org.xnio.conduits.ConduitStreamSourceChannel.read(ConduitStreamSourceChannel.java:127)

at io.undertow.channels.DetachableStreamSourceChannel.read(DetachableStreamSourceChannel.java:209)

at io.undertow.server.HttpServerExchange$ReadDispatchChannel.read(HttpServerExchange.java:2337)

at org.xnio.channels.Channels.readBlocking(Channels.java:294)

at io.undertow.servlet.spec.ServletInputStreamImpl.readIntoBuffer(ServletInputStreamImpl.java:192)

at io.undertow.servlet.spec.ServletInputStreamImpl.read(ServletInputStreamImpl.java:168)

at io.undertow.server.handlers.form.MultiPartParserDefinition$MultiPartUploadHandler.parseBlocking(MultiPartParserDefinition.java:213)

at io.undertow.servlet.spec.HttpServletRequestImpl.parseFormData(HttpServletRequestImpl.java:833)

after migrating, but it's very few of those errors, while the number of opened file descriptors increase by about 1000 per day. The error above happens when I call request.getParameter("some_param") in a servlet filter, but very rarely (and I couldn't simulate). I think this is not related to the problem of too many open files.

[tiago.matias]

Hello Lucas,

Did you find an answer to this? I'm havint the same issue with 11.0.0.Final.

[mchoma]

You can find Undertow version in starting log of server. In WF 15

10:01:45,042 INFO [org.wildfly.extension.undertow] (MSC service thread 1-4) WFLYUT0003: Undertow 2.0.15.Final starting

Also by looking into modules directory , e.g.

ls modules/system/layers/base/io/undertow/core/main

module.xml  undertow-core-2.0.15.Final.jar

Please try with version wheer UNDERTOW-961 is fixed. Best would be to use latest WF 15.

[tiago.matias]

Hello,

We just upgraded our production server to WF 15.0.0.Final last night and we're already seeing some file descriptors opened for deleted files:

Should we sorry? Maybe too soon to tell ?

root@VM-JAVA-1:~# lsof -u wildfly  | grep REG | grep deleted

java      1374 wildfly 1295r      REG              252,0      921  917533 /opt/wildfly-15.0.0.Final/standalone/tmp/digital-archive.war/undertow449317228871190919upload (deleted)

java      1374 wildfly 1296r      REG              252,0      909  917530 /opt/wildfly-15.0.0.Final/standalone/tmp/digital-archive.war/undertow1381452706943937474upload (deleted)

java      1374 wildfly 1378r      REG              252,0  179171  917521 /opt/wildfly-15.0.0.Final/standalone/tmp/digital-archive.war/undertow8628358772919141786upload (deleted)

java      1374 wildfly 1379r      REG              252,0    73306  917517 /opt/wildfly-15.0.0.Final/standalone/tmp/digital-archive.war/undertow6672135087149458107upload (deleted)

java      1374 wildfly 1380r      REG              252,0      819  917525 /opt/wildfly-15.0.0.Final/standalone/tmp/digital-archive.war/undertow989306402113328903upload (deleted)

java      1374 wildfly 1381r      REG              252,0      984  917529 /opt/wildfly-15.0.0.Final/standalone/tmp/digital-archive.war/undertow588232341959414017upload (deleted)

java      1374 wildfly 1382r      REG              252,0    25948  917526 /opt/wildfly-15.0.0.Final/standalone/tmp/digital-archive.war/undertow3449632209289191724upload (deleted)

java      1374 wildfly 1390r      REG              252,0  395456  917518 /opt/wildfly-15.0.0.Final/standalone/tmp/digital-archive.war/undertow4303357869775752008upload (deleted)

java      1374 wildfly 1395r      REG              252,0  720896  917524 /opt/wildfly-15.0.0.Final/standalone/tmp/digital-archive.war/undertow6438065975913598240upload (deleted)

java      1374 wildfly 1402r      REG              252,0    73840  917527 /opt/wildfly-15.0.0.Final/standalone/tmp/digital-archive.war/undertow4272517584239424436upload (deleted)

java      1374 wildfly 1409r      REG              252,0  296657  917522 /opt/wildfly-15.0.0.Final/standalone/tmp/digital-archive.war/undertow1297457765784999970upload (deleted)

java      1374 wildfly 1434r      REG              252,0  843776  917534 /opt/wildfly-15.0.0.Final/standalone/tmp/digital-archive.war/undertow300513679563620745upload (deleted)

java      1374 wildfly 1438r      REG              252,0  141312  917531 /opt/wildfly-15.0.0.Final/standalone/tmp/digital-archive.war/undertow7047522387650983416upload (deleted)

java      1374 wildfly 1439r      REG              252,0      834  917523 /opt/wildfly-15.0.0.Final/standalone/tmp/digital-archive.war/undertow36615172453706595upload (deleted)

java      1374 wildfly 1441r      REG              252,0  451072  917535 /opt/wildfly-15.0.0.Final/standalone/tmp/digital-archive.war/undertow6852111850426143302upload (deleted)

java      1374 wildfly 1444r      REG              252,0      839  917528 /opt/wildfly-15.0.0.Final/standalone/tmp/digital-archive.war/undertow6903339160824507852upload (deleted)

java      1374 wildfly 1451r      REG              252,0    1075  917532 /opt/wildfly-15.0.0.Final/standalone/tmp/digital-archive.war/undertow7217445821571155577upload (deleted)

root@VM-JAVA-1:~#

[mchoma]

So what is the scenario? What are these standalone/tmp/digital-archive.war/undertow<UUID>upload files? How you upload files? Does Undertow has any upload mechanism? Or you use something different for uploading the files?

[tiago.matias]

Those are opened file descriptors for files that were deleted. Luckily via /proc we managed to confirm that the contents of these files contain data that is uploaded via a REST POST call on our application. The application itself is based on spring 5. this entry point in particular:

@RequestMapping(value = "/document/{documentTypeId}/upload", method = RequestMethod.POST, consumes = { "multipart/form-data" })

public ResponseEntity<RestOperationResult> uploadDocument(@PathVariable String documentTypeId, @RequestParam("file") MultipartFile file, @RequestParam("metadata") String jsonMap) {

}

Note, perhaps a problem caused by spring itself ?

[mchoma]

Thats option it is problem of application code itself. Could you prepare some sort of reproducer showing problem is really in undertow itself? Either similar app in other tool (RestEasy?) or try you app on other server?

How are these files deleted?

[tiago.matias]

I can try to build a minimal example to reproduce it. It will take me some time.

Regarding your question on how are these files deleted: Well, since i'm not creating then explicitly my solution has been "service wildfly restart".

Are there any options in undertow subsystem that might control this ?

[jaikiran]

It's probably this issue [UNDERTOW-1474] Undertow multi-part upload can potentially leak file descriptors - JBoss Issue Tracker

[lucasbasquerotto]

I fixed this problem (at least in my case). This was not a Wildfly issue actually.

(I was not notified of new comments in this post, that's why I'm replying only now.)

I was creating the file with Files.createTempFile() and called File.deleteOnExit() right after, but, not to my knowledge before:

Deletion will be attempted only for normal termination of the virtual machine

(https://docs.oracle.com/javase/8/docs/api/java/io/File.html#deleteOnExit--).

This means that only when the docker container was restarted (and consequently the Java VM was terminated) the files were deleted, which actually was what happened like I said in the 1st post.

Now I'm not using File.deleteOnExit()  anymore and instead I'm calling delete explicitly in a finally block.

To make the code more generic, I've used a interface to save the contents in the file and another to actually use the file, like bellow:

public class FileUploadUtil

     private static interface WriteToFile {

          public void run(File file) throws IOException;

     }

     private static interface UseFile {

          public void run(File file) throws IOException;

     }

     public static void createAndUseTempFile(InputStream is, UseFile use) throws IOException {

          createAndUseTempFile((file) -> {

               try (FileOutputStream fos = new FileOutputStream(file)) {

                    byte[] bytes = new byte[1024];

                    int read;

                    while ((read = is.read(bytes)) != -1) {

                         fos.write(bytes, 0, read);

                    }

                    fos.flush();

               }

          }, use, "tmp");

     }

     public static void createAndUseTempFile(Image image, UseFile use, String extension) throws IOException {

          createAndUseTempFile((file) -> image.writeToFile(file), use, extension);

     }

     private static void createAndUseTempFile(WriteToFile write, UseFile use, String extension) throws IOException {

          File file = null;

          try {

               String key = System.currentTimeMillis() + "-" + UUID.randomUUID().toString();

               String suffix = (extension != null) ? ("." + extension) : null;

               file = File.createTempFile(key, suffix);

               write.run(file);

               use.run(file);

          } finally {

               if (file != null) {

                    file.delete();

               }

          }

     }

}

(The class Image is a custom class in my code to handle images, it's not necessary to use it)

So, for example, if I have an InputStream, the file name and the extension, I can use it very easily with lambda like:

FileUploadUtil.createAndUseTempFile(inputStream, (file) -> doSomething(file, completeFileName, extension));

@Tiago Matias

In my code I have javax.servlet.http.Part and retrieve a InputStream from it:

try (InputStream inputStream = filePart.getInputStream()) {

     uploadFile(fileInfo, inputStream);

}

Where fileInfo is just some regular object with some fields like name and extension and the method uploadFile ends up making a call similar the example I've posted above, with the InputStream. I don't know exactly the difference between the classes Part and MultipartFile (like in your case), but I hope it helps, in the case you too are calling File.deleteOnExit().

[tiago.matias]

Well, we are not explicitly closing or deleting the file. The person who wrote the code just uses the MultiPartFile, extracts the InputStream and then forgets about it.

We're going to test closing the InputStream and checking if it has any effect. I still believe this is the  Undertow issue [UNDERTOW-1474] which has a fix version of 2.0.17. So, probably we will have to wait until this version reaches wildfly to confirm.

[jaikiran]

tiago.matias  wrote:

We're going to test closing the InputStream and checking if it has any effect. I still believe this is the  Undertow issue [UNDERTOW-1474] which has a fix version of 2.0.17. So, probably we will have to wait until this version reaches wildfly to confirm.

WildFly 16.0.0.Beta1 has been released Downloads · WildFly  and that has the Undertow version which has this fix. So you might want to try it out there.