Avoid NPE on preallocated exception without message #1409

zkejid · 2017-07-22T10:51:43Z

Hello.

I'm trying to make my own research on bitconj codebase. During test execution I ran into NPE in code added by commit 83995e9. There is check, which doesn't expect exception message to be null. So I just made additional null-check, so it will not throw NPE and will not log noisy messages.

The cause is an optimisation in HotSpot. Here is an article about it: http://jawspeak.com/2010/05/26/hotspot-caused-exceptions-to-lose-their-stack-traces-in-production-and-the-fix/

My solution is not so good. The best solution would be to completely avoid 'legal' exceptions in this case. However, my knowledge is not enough for it.

Hope this helps.

- There is hot exception usage during tests execution, so HotSpot makes optimization. Optimization could be disabled with -XX:-OmitStackTraceInFastThrow. However this case can be solved with additional check in code. - Null message means there was a lot of exceptions before, so no need to log.warn about it one more time.

Polve · 2017-07-22T11:15:58Z

Doe this problem arise only on very old versions of java?

zkejid · 2017-07-22T11:53:39Z

Doe this problem arise only on very old versions of java?

No. Preallocated exception (NPE, ClassCastException, ArrayIndexOutOfBoundsException, etc) is the feature of HotSpot JVM. If your code produces a lot of exceptions, like it does during tests execution, JVM starts throwing exception without message and stacktrace. It improves performance. But code in catch clause should work properly with such empty exception instance.

I reproduced the issue running org.bitcoinj.script.ScriptTest#dataDrivenInvalidTransactions until failure. This test breaks on second hundred of executions.

here is my environment:

java version "1.8.0_131"
Java(TM) SE Runtime Environment (build 1.8.0_131-b11)
Java HotSpot(TM) Server VM (build 25.131-b11, mixed mode)

zkejid · 2017-07-22T12:12:18Z

Oops. Looks like there is one more "until failure" issue in org.bitcoinj.wallet.WalletTest#basicSpendingWithEncryptedWallet. Test fails on ~175 sweep with exception

java.lang.IllegalArgumentException: private key exceeds 32 bytes: {} bits [376]

	at com.google.common.base.Preconditions.checkArgument(Preconditions.java:180)
	at org.bitcoinj.core.ECKey.<init>(ECKey.java:193)
	at org.bitcoinj.crypto.DeterministicKey.<init>(DeterministicKey.java:69)
	at org.bitcoinj.crypto.DeterministicKey.derivePrivateKeyDownwards(DeterministicKey.java:427)
	at org.bitcoinj.crypto.DeterministicKey.findOrDeriveEncryptedPrivateKey(DeterministicKey.java:406)
	at org.bitcoinj.crypto.DeterministicKey.decrypt(DeterministicKey.java:377)
	at org.bitcoinj.crypto.DeterministicKey.decrypt(DeterministicKey.java:43)
	at org.bitcoinj.core.ECKey.decrypt(ECKey.java:1113)
	at org.bitcoinj.crypto.DeterministicKey.decrypt(DeterministicKey.java:388)
	at org.bitcoinj.crypto.DeterministicKey.decrypt(DeterministicKey.java:43)
	at org.bitcoinj.wallet.DecryptingKeyBag.maybeDecrypt(DecryptingKeyBag.java:50)
	at org.bitcoinj.wallet.DecryptingKeyBag.findKeyFromPubHash(DecryptingKeyBag.java:67)
	at org.bitcoinj.core.TransactionOutPoint.getConnectedRedeemData(TransactionOutPoint.java:169)
	at org.bitcoinj.core.TransactionInput.getConnectedRedeemData(TransactionInput.java:295)
	at org.bitcoinj.wallet.Wallet.signTransaction(Wallet.java:4091)
	at org.bitcoinj.wallet.Wallet.completeTx(Wallet.java:4028)
	at org.bitcoinj.wallet.WalletTest.basicSpendingCommon(WalletTest.java:340)
	at org.bitcoinj.wallet.WalletTest.basicSpendingWithEncryptedWallet(WalletTest.java:164)

schildbach · 2017-07-23T10:43:06Z

Thanks for finding this! I was already trying to investigate into these sporadic unit test failures, but failed and would have searched forever.

I wonder if we should perhaps disable this optimization for the tests. According to the article you linked, the -XX:-OmitStackTraceInFastThrow flag would accomplish this. Any thoughts?

zkejid · 2017-07-23T12:00:15Z

PR addresses issue in production code, and user can face the same problem while using bitconj. Also, this code goes against javadoc for java.lang.Throwable#getMessage:

 @return  the detail message string of this {@code Throwable} instance
          (which may be {@code null}).

Don't know if there could be more ways to get null in message. So I think it is better to change code than Travis configuration.

Flag should help. It is OK as a temporary solution. Or if you'd like to see all stacktraces in build log, no matter how many exceptions were thrown before. However this option would shadow bugs similar to this one.

zkejid · 2017-07-23T12:14:47Z

Also I can look for more use cases of getMessage, which can lead to the same NPE.

schildbach · 2017-07-23T12:32:09Z

Ok I see your point about production code. Ideally production code should never depend on the exception message. However in this case I guess the upstream API just didn't think about this case, and upstream APIs are difficult to fix/enhance. I'm willing to merge your patch, but I think we should document it a bit in code.

As far as I could see, there are no other dependencies of production code on the exception message (except printing it to a log, wrapping it a domain specific exception, etc.). However, we have tons of unit tests that assert for a specific exception message. In this case imho we have no other choice but to fail the test, be it through an (unexpected) NullPointerException or by properly failing the assert – the outcome will be the same, the test will fail. At the same time, running the tests will likely be the only "usecase" that raises enough exceptions to trigger the HotSpot optimization. Therefore, I still suggest disabling the optimization for the tests.

schildbach · 2017-07-23T12:33:51Z

Yes, please feel free to look for other instances of production code depending on the value of or the non-null-ness of getMessage().

zkejid · 2017-07-23T12:51:45Z

I'm willing to merge your patch, but I think we should document it a bit in code.

Should I change my PR somehow? (I'm sorry, I don't get it clear enough from your message, so have to ask :) )

schildbach · 2017-07-23T12:56:34Z

If you find other similar cases in production code, feel free to add more commits. I will write a line or two of documentation when merging.

Meanwhile, I've proposed a patch for disabling the optimization in unit tests: #1412

zkejid · 2017-07-23T13:36:33Z

There is one more case potentially leading to NPE. Proto.Error builder doesn't allow null arguments and throws NPE. I've put an empty string for null messages.

coveralls · 2017-07-23T13:37:47Z

Coverage remained the same at 72.601% when pulling 165d6fa on zkejid:preallocatedExceptionNPE into 89fb8c3 on bitcoinj:master.

coveralls · 2017-07-23T13:47:10Z

Coverage remained the same at 72.601% when pulling 9d7857b on zkejid:preallocatedExceptionNPE into 89fb8c3 on bitcoinj:master.

schildbach · 2017-07-23T14:24:56Z

core/src/main/java/org/bitcoinj/protocols/channels/PaymentChannelServer.java

@@ -527,7 +527,7 @@ private void error(String message, Protos.Error.ErrorCode errorCode, CloseReason
        Protos.Error.Builder errorBuilder;
        errorBuilder = Protos.Error.newBuilder()
                .setCode(errorCode)
-                .setExplanation(message);


Hmm, explanation is optional in the protobuf. This means the better way would be to not set the explanation at all rather than set it to the empty string.

schildbach · 2017-07-23T14:25:26Z

core/src/main/java/org/bitcoinj/protocols/channels/PaymentChannelServer.java

@@ -527,7 +527,7 @@ private void error(String message, Protos.Error.ErrorCode errorCode, CloseReason
        Protos.Error.Builder errorBuilder;
        errorBuilder = Protos.Error.newBuilder()
                .setCode(errorCode)
-                .setExplanation(message);
+                .setExplanation(message != null ? message : "");


…same here.

- 'explanation' argument in builder should not be null.

coveralls · 2017-07-24T14:31:38Z

Coverage decreased (-0.05%) to 72.55% when pulling d9f0aa8 on zkejid:preallocatedExceptionNPE into 6b42e47 on bitcoinj:master.

schildbach · 2017-07-24T15:41:42Z

I squashed, added some comments and merged. Again, thanks a lot for investing your time into this issue! I'm glad this is now fixed.

schildbach added the Priority high label Jul 23, 2017

schildbach mentioned this pull request Jul 23, 2017

Unit tests: Disable a nasty HotSpot optimization that causes exception messages… #1412

Merged

schildbach reviewed Jul 23, 2017

View reviewed changes

Avoid NPE on building message with protobuff

d9f0aa8

- 'explanation' argument in builder should not be null.

zkejid force-pushed the preallocatedExceptionNPE branch from 9d7857b to d9f0aa8 Compare July 24, 2017 14:24

schildbach closed this Jul 24, 2017

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Avoid NPE on preallocated exception without message #1409

Avoid NPE on preallocated exception without message #1409

zkejid commented Jul 22, 2017 •

edited

Polve commented Jul 22, 2017

zkejid commented Jul 22, 2017

zkejid commented Jul 22, 2017

schildbach commented Jul 23, 2017

zkejid commented Jul 23, 2017 •

edited

zkejid commented Jul 23, 2017

schildbach commented Jul 23, 2017

schildbach commented Jul 23, 2017

zkejid commented Jul 23, 2017 •

edited

schildbach commented Jul 23, 2017

zkejid commented Jul 23, 2017

coveralls commented Jul 23, 2017

coveralls commented Jul 23, 2017

schildbach Jul 23, 2017

schildbach Jul 23, 2017

coveralls commented Jul 24, 2017

schildbach commented Jul 24, 2017

Avoid NPE on preallocated exception without message #1409

Avoid NPE on preallocated exception without message #1409

Conversation

zkejid commented Jul 22, 2017 • edited

Polve commented Jul 22, 2017

zkejid commented Jul 22, 2017

zkejid commented Jul 22, 2017

schildbach commented Jul 23, 2017

zkejid commented Jul 23, 2017 • edited

zkejid commented Jul 23, 2017

schildbach commented Jul 23, 2017

schildbach commented Jul 23, 2017

zkejid commented Jul 23, 2017 • edited

schildbach commented Jul 23, 2017

zkejid commented Jul 23, 2017

coveralls commented Jul 23, 2017

coveralls commented Jul 23, 2017

schildbach Jul 23, 2017

Choose a reason for hiding this comment

schildbach Jul 23, 2017

Choose a reason for hiding this comment

coveralls commented Jul 24, 2017

schildbach commented Jul 24, 2017

zkejid commented Jul 22, 2017 •

edited

zkejid commented Jul 23, 2017 •

edited

zkejid commented Jul 23, 2017 •

edited