Notice: In order to edit this ticket you need to be either: a Product Owner, The owner or the reporter of the ticket, or, in case of a Task not yet assigned, a team_member"

Task #11081 (closed)

Opened 6 years ago

Closed 5 years ago

Ice SSL exception

Reported by: jamoore Owned by: bpindelski
Priority: minor Milestone: 5.1.0
Component: General Version: 4.4.10
Keywords: n.a. Cc: jburel, wmoore, mtbcarroll
Resources: n.a. Referenced By: n.a.
References: n.a. Remaining Time: n.a.
Sprint: n.a.

Description

On restarting the server (./build.py hot-server) and running an integration test, I received an odd (and one-of-a-kind to date) exception from Ice. Likely this is not something we can workaround, but perhaps an exception we will need to handle

(ome1)jamoore@blue:/opt/ome2/components/tools/OmeroPy$ ../../../build.py test -DTEST=integration.chgrp.TestChgrp.testChgrpOneDatasetFilesetOK
Buildfile: /opt/ome2/components/tools/OmeroPy/build.xml
Entering /opt/ome2/components/tools/OmeroPy...

python-test:
Entering /opt/ome2/components/tools/OmeroPy...

python-test-single:
WARNING: '' not a valid package name; please use only.-separated package names in setup.py
WARNING: '' not a valid package name; please use only.-separated package names in setup.py
running test
running egg_info
writing target/omero_client.egg-info/PKG-INFO
writing top-level names to target/omero_client.egg-info/top_level.txt
writing dependency_links to target/omero_client.egg-info/dependency_links.txt
writing target/omero_client.egg-info/PKG-INFO
writing top-level names to target/omero_client.egg-info/top_level.txt
writing dependency_links to target/omero_client.egg-info/dependency_links.txt
reading manifest file 'target/omero_client.egg-info/SOURCES.txt'
writing manifest file 'target/omero_client.egg-info/SOURCES.txt'
running build_ext
testChgrpOneDatasetFilesetOK (integration.chgrp.TestChgrp) ... ERROR
======================================================================
ERROR: testChgrpOneDatasetFilesetOK (integration.chgrp.TestChgrp)
----------------------------------------------------------------------
Traceback (most recent call last):
  File "/opt/ome2/components/tools/OmeroPy/test/integration/chgrp.py", line 336, in testChgrpOneDatasetFilesetOK
    images = self.importMIF(2, client=client)
  File "/opt/ome2/components/tools/OmeroPy/test/integration/library.py", line 220, in importMIF
    pixelIds = self.import_image(filename=fake.abspath(), client=client)
  File "/opt/ome2/components/tools/OmeroPy/test/integration/library.py", line 185, in import_image
    raise Exception("import failed: [%r] %s\n%s" % (args, rc, err))
Exception: import failed: [['/opt/venv/ome1/bin/python', './bin/omero', '-s', 'localhost', '-k', '8e093dc1-dd2c-4b00-991b-116f3caa0259', '-p', '4064', 'import', '--', path('/home/jamoore/omero/tmp/omero_jamoore/10534/importMIFm4P0Qb&series=2.fake')]] 2
Joined session 8e093dc1-dd2c-4b00-991b-116f3caa0259 (e8830f0f-8de9-4e49-a70d-10594a81bb97@localhost:4064). Idle timeout: 10.0 min. Current group: 7e7fbabf-f8fd-4c0d-9cd1-76d21a612256
2013-06-07 08:33:19,158 0          [      main] INFO          ome.formats.importer.ImportConfig  - OMERO Version: 5.0.0-alpha3-DEV-ice34
2013-06-07 08:33:19,162 4          [      main] INFO          ome.formats.importer.ImportConfig  - Bioformats version: 4.5-DEV revision: 7e87b37 date: 3 June 2013
2013-06-07 08:33:19,407 249        [      main] INFO      ome.formats.importer.ImportCandidates  - Depth: 4 Metadata Level: MINIMUM
2013-06-07 08:33:19,412 254        [      main] DEBUG                     loci.formats.Memoizer  - skipping memo: no directory given
2013-06-07 08:33:19,446 288        [      main] DEBUG                     loci.formats.Memoizer  - start[1370586799412] time[34] tag[loci.formats.Memoizer.setId]
2013-06-07 08:33:19,452 294        [      main] INFO      ome.formats.importer.ImportCandidates  - 1 file(s) parsed into 1 group(s) with 1 call(s) to setId in 43ms. (45ms total) [0 unknowns]
2013-06-07 08:33:21,627 2469       [      main] INFO       ome.formats.OMEROMetadataStoreClient  - Attempting initial SSL connection to localhost:4064
2013-06-07 08:33:21,977 2819       [      main] ERROR  formats.importer.cli.CommandLineImporter  - Error during import process.
Ice.SecurityException
    reason = "IceSSL: handshake error"
	at IceInternal.ConnectRequestHandler.getConnection(ConnectRequestHandler.java:240)
	at IceInternal.ConnectRequestHandler.sendRequest(ConnectRequestHandler.java:138)
	at IceInternal.Outgoing.invoke(Outgoing.java:66)
	at Ice._ObjectDelM.ice_isA(_ObjectDelM.java:30)
	at Ice.ObjectPrxHelperBase.ice_isA(ObjectPrxHelperBase.java:111)
	at Ice.ObjectPrxHelperBase.ice_isA(ObjectPrxHelperBase.java:77)
	at Glacier2.RouterPrxHelper.checkedCast(RouterPrxHelper.java:2268)
	at omero.client.getRouter(client.java:749)
	at omero.client.createSession(client.java:672)
	at omero.client.joinSession(client.java:602)
	at ome.formats.OMEROMetadataStoreClient.initialize(OMEROMetadataStoreClient.java:657)
	at ome.formats.importer.ImportConfig.createStore(ImportConfig.java:298)
	at ome.formats.importer.cli.CommandLineImporter.<init>(CommandLineImporter.java:97)
	at ome.formats.importer.cli.CommandLineImporter.main(CommandLineImporter.java:479)
Caused by: javax.net.ssl.SSLException: Received fatal alert: bad_record_mac
	at sun.security.ssl.Alerts.getSSLException(Alerts.java:208)
	at sun.security.ssl.SSLEngineImpl.fatal(SSLEngineImpl.java:1630)
	at sun.security.ssl.SSLEngineImpl.fatal(SSLEngineImpl.java:1598)
	at sun.security.ssl.SSLEngineImpl.recvAlert(SSLEngineImpl.java:1767)
	at sun.security.ssl.SSLEngineImpl.readRecord(SSLEngineImpl.java:1063)
	at sun.security.ssl.SSLEngineImpl.readNetRecord(SSLEngineImpl.java:887)
	at sun.security.ssl.SSLEngineImpl.unwrap(SSLEngineImpl.java:761)
	at javax.net.ssl.SSLEngine.unwrap(SSLEngine.java:624)
	at IceSSL.TransceiverI.handshakeNonBlocking(TransceiverI.java:444)
	at IceSSL.TransceiverI.initialize(TransceiverI.java:43)
	at Ice.ConnectionI.initialize(ConnectionI.java:1831)
	at Ice.ConnectionI.message(ConnectionI.java:1038)
	at IceInternal.ThreadPool.run(ThreadPool.java:302)
	at IceInternal.ThreadPool.access$300(ThreadPool.java:12)
	at IceInternal.ThreadPool$EventHandlerThread.run(ThreadPool.java:643)
	at java.lang.Thread.run(Thread.java:722)
----------------------------------------------------------------------
Ran 1 test in 5.341s
FAILED (errors=1)
Result: 1
Entering /opt/ome2/components/tools/OmeroPy...

Attachments (1)

ConnectionTest.java​ (922 bytes) - added by bpindelski 6 years ago.
Class for connection testing

Download all attachments as: .zip

Change History (10)

comment:1 Changed 6 years ago by mtbcarroll

  • Cc mtbcarroll added

I just saw this trying to run the OmeroJava integration tests on dev_4_4:

Ice.SecurityException
    reason = "IceSSL: handshake error"
IceInternal.ConnectRequestHandler.getConnection(ConnectRequestHandler.java:240)
IceInternal.ConnectRequestHandler.sendRequest(ConnectRequestHandler.java:138)
IceInternal.Outgoing.invoke(Outgoing.java:66)
Ice._ObjectDelM.ice_isA(_ObjectDelM.java:30)
Ice.ObjectPrxHelperBase.ice_isA(ObjectPrxHelperBase.java:111)
Ice.ObjectPrxHelperBase.ice_isA(ObjectPrxHelperBase.java:77)
Glacier2.RouterPrxHelper.checkedCast(RouterPrxHelper.java:2268)
omero.client.getRouter(client.java:727)
omero.client.createSession(client.java:650)
integration.AbstractServerTest.newUserInGroup(AbstractServerTest.java:525)
integration.AbstractServerTest.newUserAndGroup(AbstractServerTest.java:286)
integration.AbstractServerTest.newUserAndGroup(AbstractServerTest.java:263)
integration.DeleteServiceTest.createNewUser(DeleteServiceTest.java:216)
sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57)
sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
java.lang.reflect.Method.invoke(Method.java:601)
org.testng.internal.MethodInvocationHelper.invokeMethod(MethodInvocationHelper.java:74)
org.testng.internal.Invoker.invokeConfigurationMethod(Invoker.java:525)
org.testng.internal.Invoker.invokeConfigurations(Invoker.java:202)
org.testng.internal.Invoker.invokeMethod(Invoker.java:613)
org.testng.internal.Invoker.invokeTestMethod(Invoker.java:846)
org.testng.internal.Invoker.invokeTestMethods(Invoker.java:1170)
org.testng.internal.TestMethodWorker.invokeTestMethods(TestMethodWorker.java:125)
org.testng.internal.TestMethodWorker.run(TestMethodWorker.java:109)
org.testng.TestRunner.runWorkers(TestRunner.java:1125)
org.testng.TestRunner.privateRun(TestRunner.java:749)
org.testng.TestRunner.run(TestRunner.java:600)
org.testng.SuiteRunner.runTest(SuiteRunner.java:317)
org.testng.SuiteRunner.runSequentially(SuiteRunner.java:312)
org.testng.SuiteRunner.privateRun(SuiteRunner.java:274)
org.testng.SuiteRunner.run(SuiteRunner.java:223)
org.testng.SuiteRunnerWorker.runSuite(SuiteRunnerWorker.java:52)
org.testng.SuiteRunnerWorker.run(SuiteRunnerWorker.java:86)
org.testng.TestNG.runSuitesSequentially(TestNG.java:1007)
org.testng.TestNG.runSuitesLocally(TestNG.java:932)
org.testng.TestNG.run(TestNG.java:868)
org.testng.TestNG.privateMain(TestNG.java:1150)
org.testng.TestNG.main(TestNG.java:1114)
Caused by: javax.net.ssl.SSLException: Received fatal alert: bad_record_mac

When I get a IceSSL: handshake error in running integration tests, I just rerun them and it is then gone (or at least elsewhere!).

comment:2 Changed 6 years ago by jamoore

  • Milestone changed from Unscheduled to 5.1.0
  • Owner set to bpindelski
  • Version set to 4.4.10

Passing to Blazej for a review

comment:3 Changed 6 years ago by bpindelski

As far as I managed to find out, this could be caused by an SSL protocol version (2 vs. 3) mismatch or a TCP packet with an invalid checksum (rather unlikely). I wonder how much the node load has influence on the frequency of this bug appearing...

Relevant resources:

comment:4 Changed 6 years ago by jamoore

If we need to define SSL version properties or similar, can certainly do that in the integration job to see if things get better:

How regularly are the failures in the test logs?

comment:5 Changed 6 years ago by bpindelski

Josh: We saw the failure only once till now. If it happens again, we will have to look into hard-coding SSL versions between the OMERO.server and the JVM running TestNG.

comment:6 Changed 6 years ago by bpindelski

This is happening now almost daily on ome-c6100-3. I haven't managed yet to get the output of "-Djavax.net.debug=ssl" visible. It's also impossible for me to reproduce the error locally.

comment:7 Changed 6 years ago by bpindelski

I think I'm finally on the right path. This is most probably caused by a mismatch between the JVM and OpenSSL on the target machine. A simple test class fails almost instantly on the affected node (file attached).

Changed 6 years ago by bpindelski

Class for connection testing

comment:8 Changed 6 years ago by bpindelski

The difference between nodes:

  • on the failing node: openssl-1.0.0-25.el6_3.1.x86_64 and java-1.7.0-openjdk-1.7.0.9-2.3.7.1.el6_3.x86_64
  • on the working node: openssl-1.0.0-20.el6_2.5.x86_64 and java-1.7.0-openjdk-devel-1.7.0.5-2.2.1.el6_3.x86_64

comment:9 Changed 5 years ago by bpindelski

  • Resolution set to worksforme
  • Status changed from new to closed

Closing. This issue doesn't manifest itself anymore on the node running the 5.1 tests. It was a strange combination of Java and OpenSSL, which was almost impossible to diagnose.

Note: See TracTickets for help on using tickets. You may also have a look at Agilo extensions to the ticket.

1.3.13-PRO © 2008-2011 Agilo Software all rights reserved (this page was served in: 0.78488 sec.)

© 2000-2014 University of Dundee & Open Microscopy Environment. Creative Commons Attribution 3.0 Unported License
OME source code is available under the GNU General public license or through commercial license from Glencoe Software

We're Hiring!