Is your JVM leaking file descriptors - like mine?

Foreword: The two issues described here, were discovered and fixed more than a year ago. This article only serves as historical proof, and a beginners' guide on tackling file descriptor leaks in Java.

In Ultra ESB we use an in-memory RAM disk file cache for fast and garbage-free payload handling. Some time back, we faced an issue on our shared SaaS AS2 Gateway where this cache was leaking file descriptors over time. Eventually leading to too many open files errors when the system ulimit was hit.

The Legion of the Bouncy Castle: leftovers from your stream-backed MIME parts?

One culprit, we found, was Bouncy Castle - the famous security provider that had been our profound love since the Ultra ESB Legacy days.

With some simple tooling we found that BC had the habit of calling getContent() on MIME parts in order to determine their type (say, instanceof checks). True, this wasn't a crime in itself; but most of our MIME parts were file-backed, with a file-cache file on the other end - meaning that every getContent() opens a new stream to the file. So now there are stray streams (and hence file descriptors) pointing to our file cache.

Enough of these, and we would exhaust the file descriptor quota allocated to the Ultra ESB (Java) process.

Solution? Make 'em lazy!

We didn't want to mess with the BC codebase. So we found a simple solution: create all file-backed MIME parts with "lazy" streams. Our (former) colleague Rajind wrote a LazyFileInputStream - inspired by LazyInputStream from jboss-vfs - that opens the actual file only when a read is attempted.

BC was happy, and so was the file cache; but we were the happiest.

Hibernate JPA: cleaning up after supper, a.k.a closing consumed streams

Another bug we spotted was that some database operations were leaving behind unclosed file handles. Apparently this was only when we were feeding stream-backed blobs to Hibernate, where the streams were often coming from file cache entries.

After some digging, we came up with a theory that Hibernate was not closing the underlying streams of these blob entries. (It made sense because the java.sql.Blob interface does not expose any methods that Hibernate could use to manipulate the underlying data sources.) This was a problem, though, because the discarded streams (and the associated file handles) would not get released until the next GC.

This would have been fine for a short-term app, but a long-running one like ours could easily run out of file descriptors; such as in case of a sudden and persistent spike.

Solution? Make 'em self-closing!

We didn't want to lose the benefits of streaming, but we didn't have control over our streams either. You might say we should have placed our streams in auto-closeable constructs (say, try-with-resources). Nice try; but sadly, Hibernate was reading them outside of our execution scope (especially in @Transactional flows). As soon as we started closing the streams within our code scope, our database operations started to fail miserably - screaming "stream already closed!".

When in Rome, do as Romans do, they say.

So, instead of messing with Hibernate, we decided we would take care of the streams ourselves.

Rajind (yeah, him again) hacked together a SelfClosingInputStream wrapper. This would keep track of the amount of data read from the underlying stream, and close it up as soon as the last byte was read.

(We did consider using existing options like AutoCloseInputStream from Apache commons-io; but it occurred that we needed some customizations here and there - like detailed trace logging.)

Bottom line

When it comes to resource management in Java, it is quite easy to over-focus on memory and CPU (processing), and forget about the rest. But virtual resources - like ephemeral ports and per-process file descriptors - can be just as important, if not more.

Especially on long-running processes like our AS2 Gateway SaaS application, they can literally become silent killers.

You can detect this type of "leaks" in two main ways:

• "single-cycle" resource analysis: run a single, complete processing cycle, comparing resource usage before and after
• long-term monitoring: continuously recording and analyzing resource metrics to identify trends and anomalies

In any case, fixing the leak is not too difficult; once you have a clear picture of what you are dealing with.

Good luck with hunting down your resource-hog d(a)emons!

Harmonizing UltraESB and FTP/S: Troubleshooting Connectivity

The UltraESB has built-in capability of communicating with FTP, FTP/S, SFTP and local filesystem (file://) endpoints. While setting up the other file transports might be easy, FTP/S can be problematic, especially if you start from a fresh FTP/S installation.

Assuming a local FTP/S server setup (e.g. vsftpd) with a user ftp having password ftp and home directory /srv/ftp (quoting vsftpd default settings), you might encounter a few problems when trying to submit files to an endpoint URL such as ftps://ftp:ftp@localhost/srv/ftp/, on the UESB side.

These usually occur at FTP level, so in order to find the actual causes you will have to enable TRACE logging on the org.adroitlogic.ultraesb.transport.file category in $ULTRA_HOME/conf/log4j.properties:

log4j.category.org.adroitlogic.ultraesb.transport.file=TRACE

With TRACE enabled as above, the UESB log will contain a trace of all FTP commands being executed during the transfer attempt, as:

2016-05-04 22:57:55,043 [-] [primary-1] [system] [000000I] DEBUG FTPSConnector Connecting over FTPS to URL : ftps://ftp:********@localhost/srv/ftp/ftps/send.msg?StrictHostKeyChecking=no

220 (vsFTPd 3.0.3)
AUTH TLS
234 Proceed with negotiation.
PROT P
200 PROT now Private.
USER ftp
...

If you see 530 Anonymous sessions may not use encryption. (usually followed by a stacktrace on the UESB):

...
234 Proceed with negotiation.
PROT P
200 PROT now Private.
USER ftp
530 Anonymous sessions may not use encryption.
QUIT
221 Goodbye.
2016-05-04 22:57:55,381 [-] [primary-1] [system] [000000W]  WARN FTPSConnector Login failed for FTPS server : ftps://ftp:********@localhost/srv/ftp/ftps/send.msg?StrictHostKeyChecking=no
PORT 127,0,0,1,179,254
2016-05-04 22:57:55,385 [-] [primary-1] [system] [000000W]  WARN FTPConnector Error copying file to URL : ftps://ftp:********@localhost/srv/ftp/ftps/send.msg?StrictHostKeyChecking=no
org.apache.commons.net.ftp.FTPConnectionClosedException: Connection closed without indication.
	at org.apache.commons.net.ftp.FTP.__getReply(FTP.java:313)
	at org.apache.commons.net.ftp.FTP.__getReply(FTP.java:290)
	at org.apache.commons.net.ftp.FTP.sendCommand(FTP.java:479)
	at org.apache.commons.net.ftp.FTPSClient.sendCommand(FTPSClient.java:535)
...

you would want to allow anonymous SSL sessions on your vsftpd.conf:

allow_anon_ssl=YES

(Note: Make sure you restart vsftpd after every such change!
service vsftpd restart # as root)

If the issue is 522 SSL connection failed: session reuse required:

...
234 Proceed with negotiation.
PROT P
200 PROT now Private.
USER ftp
331 Please specify the password.
PASS ftp
230 Login successful.
TYPE I
200 Switching to Binary mode.
PASV
227 Entering Passive Mode (127,0,0,1,161,222).
STOR /srv/ftp/ftps/send.msg
150 Ok to send data.
522 SSL connection failed: session reuse required
2016-05-04 22:59:07,418 [-] [primary-1] [system] [000000I] DEBUG FTPConnector FTP copy failed to : ftps://ftp:********@localhost/srv/ftp/ftps/send.msg?StrictHostKeyChecking=no
2016-05-04 22:59:07,429 [-] [primary-1] [system] [000000W]  WARN FileTransportSender Error sending message via file transport sender to : ftps://ftp:********@localhost/srv/ftp/ftps/send.msg?StrictHostKeyChecking=no

adding/updating require_ssl_reuse=NO in vsftpd.conf would resolve it.

On the other hand, if authentication fails mid-way in the SSL handshake process:

220 (vsFTPd 3.0.3)
AUTH TLS
234 Proceed with negotiation.
2016-05-04 23:05:26,907 [-] [primary-2] [system] [000000W]  WARN FTPSConnector Error connecting over FTPS to URL : ftps://ftp:********@localhost/srv/ftp/ftps/send.msg?StrictHostKeyChecking=no
javax.net.ssl.SSLHandshakeException: Received fatal alert: handshake_failure
	at sun.security.ssl.Alerts.getSSLException(Alerts.java:192)
	at sun.security.ssl.Alerts.getSSLException(Alerts.java:154)
...
	at org.adroitlogic.ultraesb.transport.file.FTPSConnector.(FTPSConnector.java:62)
	at org.adroitlogic.ultraesb.transport.file.FileSystemConnectorFactory.createConnector(FileSystemConnectorFactory.java:54)
...
	at org.adroitlogic.ultraesb.core.work.SimpleQueueWorkManager$1.run(SimpleQueueWorkManager.java:306)
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
	at java.lang.Thread.run(Thread.java:745)
2016-05-04 23:05:26,909 [-] [primary-2] [system] [000000W]  WARN FTPConnector Error copying file to URL : ftps://ftp:********@localhost/srv/ftp/ftps/send.msg?StrictHostKeyChecking=no
java.net.SocketException: Socket closed
	at java.net.SocketOutputStream.socketWrite(SocketOutputStream.java:116)
	at java.net.SocketOutputStream.write(SocketOutputStream.java:153)
...
	at org.apache.commons.net.ftp.FTP.__send(FTP.java:501)
	at org.apache.commons.net.ftp.FTP.sendCommand(FTP.java:475)
...
	at org.apache.commons.net.ftp.FTPClient.storeFile(FTPClient.java:1795)
	at org.adroitlogic.ultraesb.transport.file.FTPConnector.put(FTPConnector.java:169)
	at org.adroitlogic.ultraesb.transport.file.FileTransportSender.internalSend(FileTransportSender.java:80)
...
	at org.adroitlogic.ultraesb.core.work.SimpleQueueWorkManager$1.run(SimpleQueueWorkManager.java:306)
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
	at java.lang.Thread.run(Thread.java:745)
2016-05-04 23:05:26,919 [-] [primary-2] [system] [000000W]  WARN FileTransportSender Error sending message via file transport sender to : ftps://ftp:********@localhost/srv/ftp/ftps/send.msg?StrictHostKeyChecking=no

you might require a tcpdump (against the loopback interface (lo) in this case) for finding the cause, as neither the ESB logs (even with SSL debug logs enabled: -Djavax.net.debug=all) nor the vsftpd log would show the underlying cause properly:

# tcpdump -A -vvv -i lo
...
06:41:37.566325 IP (tos 0x0, ttl 64, id 14724, offset 0, flags [DF], proto TCP (6), length 83)
    localhost.ftp > localhost.60532: Flags [P.], cksum 0xfe47 (incorrect -> 0xc3fd), seq 21:52, ack 11, win 342, options [nop,nop,TS val 37556708 ecr 37556708], length 31: FTP, length: 31
	234 Proceed with negotiation.
E..S9.@.@..............t..(u..,....V.G.....
.=...=..234 Proceed with negotiation.

06:41:37.576134 IP (tos 0x0, ttl 64, id 15677, offset 0, flags [DF], proto TCP (6), length 294)
    localhost.60532 > localhost.ftp: Flags [P.], cksum 0xff1a (incorrect -> 0x9887), seq 11:253, ack 52, win 342, options [nop,nop,TS val 37556711 ecr 37556708], length 242: FTP, length: 242
E..&==@.@............t....,...(....V.......
.=...=.............W*...l....I...TG	R.1_........F>...d.$.(.=.&.*.k.j.
...5.....9.8.#.'.<.%.).g.@.	.../.....3.2.,.+.0.....2...../...-.1.........
.............\.
.4.2...............	.
....................................................................
06:41:37.576284 IP (tos 0x0, ttl 64, id 14725, offset 0, flags [DF], proto TCP (6), length 59)
    localhost.ftp > localhost.60532: Flags [P.], cksum 0xfe2f (incorrect -> 0xd702), seq 52:59, ack 253, win 350, options [nop,nop,TS val 37556711 ecr 37556711], length 7: FTP, length: 7
E..;9.@.@..6...........t..(...-....^./.....
.=...=........(
06:41:37.577983 IP (tos 0x0, ttl 64, id 14726, offset 0, flags [DF], proto TCP (6), length 62)
    localhost.ftp > localhost.60532: Flags [P.], cksum 0xfe32 (incorrect -> 0xd9ea), seq 59:69, ack 253, win 350, options [nop,nop,TS val 37556711 ecr 37556711], length 10: FTP, length: 10
	500 OOPS: [!ftp]
E..>9.@.@..2...........t..(...-....^.2.....
.=...=..500 OOPS: 
06:41:37.577995 IP (tos 0x0, ttl 64, id 14727, offset 0, flags [DF], proto TCP (6), length 118)
    localhost.ftp > localhost.60532: Flags [P.], cksum 0xfe6a (incorrect -> 0xe009), seq 69:135, ack 253, win 350, options [nop,nop,TS val 37556711 ecr 37556711], length 66: FTP, length: 66
	error:1408A0C1:SSL routines:ssl3_get_client_hello:no shared cipher[!ftp]
E..v9.@.@..............t..(...-....^.j.....
.=...=..error:1408A0C1:SSL routines:ssl3_get_client_hello:no shared cipher
06:41:37.578000 IP (tos 0x0, ttl 64, id 14728, offset 0, flags [DF], proto TCP (6), length 54)
    localhost.ftp > localhost.60532: Flags [P.], cksum 0xfe2a (incorrect -> 0x0bb0), seq 135:137, ack 253, win 350, options [nop,nop,TS val 37556711 ecr 37556711], length 2: FTP, length: 2
	
E..69.@.@..8...........t..(...-....^.*.....
.=...=..

06:41:37.578230 IP (tos 0x0, ttl 64, id 14729, offset 0, flags [DF], proto TCP (6), length 62)
    localhost.ftp > localhost.60532: Flags [P.], cksum 0xfe32 (incorrect -> 0xd99c), seq 137:147, ack 253, win 350, options [nop,nop,TS val 37556711 ecr 37556711], length 10: FTP, length: 10
	500 OOPS: [!ftp]
E..>9.@.@../...........t..(...-....^.2.....
.=...=..500 OOPS: 
06:41:37.578323 IP (tos 0x0, ttl 64, id 15678, offset 0, flags [DF], proto TCP (6), length 52)
    localhost.60532 > localhost.ftp: Flags [R.], cksum 0xfe28 (incorrect -> 0x18bc), seq 253, ack 147, win 342, options [nop,nop,TS val 37556711 ecr 37556711], length 0
E..4=>@.@............t....-...(....V.(.....
.=...=..

Now we have a hint on what might be going wrong:

error:1408A0C1:SSL routines:ssl3_get_client_hello:no shared cipher[!ftp]

This usually occurs if the cipher suite offered by the FTP/S server is not sufficiently strong. Adding/updating

ssl_ciphers=HIGH

in vsftpd.conf would get you through this issue.

Once you have everything in place, the UESB trace would indicate a successful transfer:

2016-05-04 23:02:08,930 [-] [primary-1] [system] [000000I] DEBUG FTPSConnector Connecting over FTPS to URL : ftps://ftp:********@localhost/srv/ftp/ftps/send.msg?StrictHostKeyChecking=no
220 (vsFTPd 3.0.3)
AUTH TLS
234 Proceed with negotiation.
PROT P
200 PROT now Private.
USER ftp
331 Please specify the password.
PASS ftp
230 Login successful.
TYPE I
200 Switching to Binary mode.
PASV
227 Entering Passive Mode (127,0,0,1,104,213).
STOR /srv/ftp/ftps/send.msg
150 Ok to send data.
226 Transfer complete.
2016-05-04 23:02:09,360 [-] [primary-1] [system] [000000I] DEBUG FTPConnector FTP copy completed successfully to : ftps://ftp:********@localhost/srv/ftp/ftps/send.msg?StrictHostKeyChecking=no