Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

OpenSSLServerSocketImplTest.pingPong[ENGINE] encounters SSLException: Unexpected engine result CLOSED #171

Closed
15characterlimi opened this issue Apr 13, 2017 · 2 comments
Closed

OpenSSLServerSocketImplTest.pingPong[ENGINE] encounters SSLException: Unexpected engine result CLOSED #171

15characterlimi opened this issue Apr 13, 2017 · 2 comments
Assignees
@flooey
Milestone
1.0.0

Comments

@15characterlimi
Copy link
Contributor

15characterlimi commented Apr 13, 2017 •
edited

I work on the Android team. While running conscrypt (*) tests on Android, we've run into an issue with conscrypt's experimental new SSL Socket implementation ("ENGINE") that leads to test failures, specifically in org.conscrypt.OpenSSLServerSocketImplTest.pingPong. The regular implementation ("DEFAULT") seems to work fine - we've only observed this issue for the experimental new "ENGINE" implementation.

(*) Our copy of conscrypt is repackaged under "com.android.org.conscrypt" and based I believe on conscrypt commit 9e569de , which is 23 days behind HEAD:

Further, we've only observed this issue on some specific devices (Nexus Player, which is x86 based, and Pixel C, which is ARM based) but not on others. I personally have been unable to reproduce this issue on a Nexus Player but others have, so there may be some additional factor that I'm unaware of.

What appears to happen during the test is that an SSLException("Unexpected engine result CLOSED") is occurs on the server thread in the background. TestServer$EchoProcessor.processMessage wraps that in a RuntimeException, which is not caught and therefore causes our test environment to shut down the entire test run (which is being executed on the main, test runner, thread). The root cause of this "Unexpected engine result CLOSED" is unclear.

Internally, we're tracking the impact of this issue on Android as bug 37271061.

I don't have good reproduction steps since I haven't personally been able to reproduce this issue yet. However, here's an log excerpt of run of Android's compatibility test suite (CTS) that encountered the issue:

04-12 03:58:47.956 28134 28150 I TestRunner: started: pingPong[DEFAULT](com.android.org.conscrypt.OpenSSLServerSocketImplTest)
04-12 03:58:47.956 28134 28134 I MonitoringInstr: Activities that are still in CREATED to STOPPED: 0
04-12 03:58:47.957 28134 28150 D CtsTestRunListener: Total memory  : 42608719
04-12 03:58:47.957 28134 28150 D CtsTestRunListener: Used memory   : 39804232
04-12 03:58:47.957 28134 28150 D CtsTestRunListener: Free memory   : 2804487
04-12 03:58:47.957 28134 28150 D CtsTestRunListener: java.io.tmpdir is:/data/user/0/android.libcore.cts/cache
04-12 03:58:47.957 28134 28150 D CtsTestRunListener: About to .exec df
04-12 03:58:47.958 28134 28150 D CtsTestRunListener: .exec returned
04-12 03:58:47.958 28134 28150 D CtsTestRunListener: Stream reader created
04-12 03:58:47.964 29656 29656 W df      : type=1400 audit(0.0:3075): avc: denied { getattr } for path="/dev/block" dev="tmpfs" ino=9112 scontext=u:r:untrusted_app:s0:c512,c768 tcontext=u:object_r:block_device:s0 tclass=dir permissive=0
04-12 03:58:47.965 29656 29656 W df      : type=1400 audit(0.0:3076): avc: denied { getattr } for path="/dev/block" dev="tmpfs" ino=9112 scontext=u:r:untrusted_app:s0:c512,c768 tcontext=u:object_r:block_device:s0 tclass=dir permissive=0
04-12 03:58:47.966 28134 28150 D CtsTestRunListener: Filesystem      1K-blocks    Used Available Use% Mounted on
04-12 03:58:47.966 28134 28150 D CtsTestRunListener: /dev/block/dm-2  25396556 2151812  23228360   9% /data
04-12 03:58:47.966 28134 28150 D CtsTestRunListener: In finally
04-12 03:58:47.966 28134 28150 D CtsTestRunListener: Now executing : com.android.org.conscrypt.OpenSSLServerSocketImplTest
04-12 03:58:47.977 28134 28150 I TestRunner: finished: pingPong[DEFAULT](com.android.org.conscrypt.OpenSSLServerSocketImplTest)
04-12 03:58:47.978 28134 28134 I MonitoringInstr: Activities that are still in CREATED to STOPPED: 0
04-12 03:58:47.978 28134 28150 I TestRunner: started: pingPong[ENGINE](com.android.org.conscrypt.OpenSSLServerSocketImplTest)
04-12 03:58:47.979 28134 28134 I MonitoringInstr: Activities that are still in CREATED to STOPPED: 0
04-12 03:58:47.991 28134 29658 W System.err: javax.net.ssl.SSLException: Unexpected engine result CLOSED
04-12 03:58:47.991 28134 29658 W System.err: 	at com.android.org.conscrypt.OpenSSLEngineSocketImpl$OutputStreamWrapper.write(OpenSSLEngineSocketImpl.java:369)
04-12 03:58:47.991 28134 29658 W System.err: 	at com.android.org.conscrypt.OpenSSLEngineSocketImpl$OutputStreamWrapper.write(OpenSSLEngineSocketImpl.java:352)
04-12 03:58:47.991 28134 29658 W System.err: 	at com.android.org.conscrypt.testing.TestServer$EchoProcessor.processMessage(TestServer.java:45)
04-12 03:58:47.991 28134 29658 W System.err: 	at com.android.org.conscrypt.testing.TestServer$ProcessTask.run(TestServer.java:131)
04-12 03:58:47.991 28134 29658 W System.err: 	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1162)
04-12 03:58:47.991 28134 29658 W System.err: 	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:636)
04-12 03:58:47.991 28134 29658 W System.err: 	at java.lang.Thread.run(Thread.java:764)
04-12 03:58:47.991 28134 28150 I TestRunner: finished: pingPong[ENGINE](com.android.org.conscrypt.OpenSSLServerSocketImplTest)
--------- beginning of crash
04-12 03:58:47.991 28134 29658 E AndroidRuntime: FATAL EXCEPTION: pool-1399-thread-1
04-12 03:58:47.991 28134 29658 E AndroidRuntime: Process: android.libcore.cts, PID: 28134
04-12 03:58:47.991 28134 29658 E AndroidRuntime: java.lang.RuntimeException: java.lang.RuntimeException: javax.net.ssl.SSLException: Unexpected engine result CLOSED
04-12 03:58:47.991 28134 29658 E AndroidRuntime: 	at com.android.org.conscrypt.testing.TestServer$ProcessTask.run(TestServer.java:135)
04-12 03:58:47.991 28134 29658 E AndroidRuntime: 	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1162)
04-12 03:58:47.991 28134 29658 E AndroidRuntime: 	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:636)
04-12 03:58:47.991 28134 29658 E AndroidRuntime: 	at java.lang.Thread.run(Thread.java:764)
04-12 03:58:47.991 28134 29658 E AndroidRuntime: Caused by: java.lang.RuntimeException: javax.net.ssl.SSLException: Unexpected engine result CLOSED
04-12 03:58:47.991 28134 29658 E AndroidRuntime: 	at com.android.org.conscrypt.testing.TestServer$EchoProcessor.processMessage(TestServer.java:48)
04-12 03:58:47.991 28134 29658 E AndroidRuntime: 	at com.android.org.conscrypt.testing.TestServer$ProcessTask.run(TestServer.java:131)
04-12 03:58:47.991 28134 29658 E AndroidRuntime: 	... 3 more
04-12 03:58:47.991 28134 29658 E AndroidRuntime: Caused by: javax.net.ssl.SSLException: Unexpected engine result CLOSED
04-12 03:58:47.991 28134 29658 E AndroidRuntime: 	at com.android.org.conscrypt.OpenSSLEngineSocketImpl$OutputStreamWrapper.write(OpenSSLEngineSocketImpl.java:369)
04-12 03:58:47.991 28134 29658 E AndroidRuntime: 	at com.android.org.conscrypt.OpenSSLEngineSocketImpl$OutputStreamWrapper.write(OpenSSLEngineSocketImpl.java:352)
04-12 03:58:47.991 28134 29658 E AndroidRuntime: 	at com.android.org.conscrypt.testing.TestServer$EchoProcessor.processMessage(TestServer.java:45)
04-12 03:58:47.991 28134 29658 E AndroidRuntime: 	... 4 more
04-12 03:58:47.992 28134 28134 I MonitoringInstr: Activities that are still in CREATED to STOPPED: 0
04-12 03:58:47.993 28134 28150 I TestRunner: started: test_handshakeWithSCTFromOCSPResponse(com.android.org.conscrypt.OpenSSLSocketImplTest)
04-12 03:58:47.994 28134 28134 I MonitoringInstr: Activities that are still in CREATED to STOPPED: 0
04-12 03:58:47.994 28134 28150 D CtsTestRunListener: Total memory  : 42608719
04-12 03:58:47.994 28134 28150 D CtsTestRunListener: Used memory   : 40675344
04-12 03:58:47.994 28134 28150 D CtsTestRunListener: Free memory   : 1933375
04-12 03:58:47.994 28134 28150 D CtsTestRunListener: java.io.tmpdir is:/data/user/0/android.libcore.cts/cache
04-12 03:58:47.994 28134 28150 D CtsTestRunListener: About to .exec df
04-12 03:58:47.996 28134 28150 D CtsTestRunListener: .exec returned
04-12 03:58:47.996 28134 28150 D CtsTestRunListener: Stream reader created
04-12 03:58:48.001  9981  9993 W ActivityManager: Force-killing crashed app android.libcore.cts at watcher's request
04-12 03:58:48.002 28134 29658 I Process : Sending signal. PID: 28134 SIG: 9
04-12 03:58:48.002  9981  9995 E memtrack: Couldn't load memtrack module
04-12 03:58:48.003  9981  9995 W android.os.Debug: failed to get memory consumption info: -1
04-12 03:58:48.006 29660 29660 W df      : type=1400 audit(0.0:3077): avc: denied { getattr } for path="/dev/block" dev="tmpfs" ino=9112 scontext=u:r:untrusted_app:s0:c512,c768 tcontext=u:object_r:block_device:s0 tclass=dir permissive=0
04-12 03:58:48.006 29660 29660 W df      : type=1400 audit(0.0:3078): avc: denied { getattr } for path="/dev/block" dev="tmpfs" ino=9112 scontext=u:r:untrusted_app:s0:c512,c768 tcontext=u:object_r:block_device:s0 tclass=dir permissive=0
04-12 03:58:48.036  9981  9993 I ActivityManager: Process android.libcore.cts (pid 28134) has died
04-12 03:58:48.036  9981  9993 W ActivityManager: Crash of app android.libcore.cts running instrumentation ComponentInfo{android.libcore.cts/android.support.test.runner.AndroidJUnitRunner}
04-12 03:58:48.038  9981  9993 I ActivityManager: Force stopping android.libcore.cts appid=10227 user=0: finished inst
04-12 03:58:48.039  9981 29662 W Binder  : Outgoing transactions from this process must be FLAG_ONEWAY
04-12 03:58:48.039  9981 29662 W Binder  : java.lang.Throwable
04-12 03:58:48.039  9981 29662 W Binder  : 	at android.os.BinderProxy.transact(Binder.java:712)
04-12 03:58:48.039  9981 29662 W Binder  : 	at android.app.IInstrumentationWatcher$Stub$Proxy.instrumentationFinished(IInstrumentationWatcher.java:160)
04-12 03:58:48.039  9981 29662 W Binder  : 	at com.android.server.am.InstrumentationReporter$MyThread.run(InstrumentationReporter.java:86)
04-12 03:58:48.039 28124 28124 D AndroidRuntime: Shutting down VM
@nmittler nmittler added this to the 1.0.0 milestone Apr 13, 2017
@nmittler
Copy link
Contributor

@15characterlimi @flooey A lot has changed since this bug was created. We should check to see if this is still and issue with the latest master.

@nmittler
Copy link
Contributor

Closing this for now. Re-open if it's still a problem.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees

@flooey flooey

Labels
None yet
Projects
None yet
Milestone
1.0.0
Development

No branches or pull requests
3 participants
@flooey @15characterlimi @nmittler