users@glassfish.java.net

Re: ACC, Web Start and IIOP/SSL

From: <glassfish_at_javadesktop.org>
Date: Wed, 12 Mar 2008 05:41:24 PST

Hi,

Thanks for your responses.

The bug I'm referring to is: Issue 3900
See: https://glassfish.dev.java.net/issues/show_bug.cgi?id=3900

The blog from Shing Wai Chang you mentioned is one of the several options I did try.
Unfortunately his explanation (being good as it is) did not solve my problem that my ACC Client is not connecting over IIOP + SSL.

To me it looks like the problem is primarily related to the SSL internal handling of the server because when I 'downgrade' the confidentiality and integrity to 'supported' I can access the method in the bean.

The main problem now is that I'm pretty much stuck.
Even after setting the debugging to ALL the log file of the server does not give me enough clues as to where to look any further.

I already re-installed the server (SJSAS 9.1_1) and jre (1.6.0_4) again.
I exported the s1as certificate from the server keystore and imported that certificate into the client truststore.
I created a new client keystore and imported that one into the server truststore.
I redeployed the ejb and client from my IDE (Eclipse 3.3 with GlassFish V2 plugin)
Lastly I ran the clientApp using webstart immediately after server startup.
I get (as expected) the login window asking for a username/password.
After entering the correct credentials, the GUI of my client never shows up (even after waiting 5 minutes)

[b]Here are the - to me - most remarkable entries in the server.log after startup of the server:[/b][i]
:
:
:
[#|2008-03-12T13:47:10.265+0100|INFO|sun-appserver9.1|javax.enterprise.system.stream.out|_ThreadID=10;_ThreadName=main;|X509KeyManager passed to SSLContext.init(): [b]need an X509ExtendedKeyManager for SSLEngine use|#][/b]
:
:
:
[#|2008-03-12T13:47:15.937+0100|INFO|sun-appserver9.1|javax.enterprise.system.container.ejb|_ThreadID=10;_ThreadName=main;|EJBSCLookup:: sc.getEjbContainerAvailabilityEnabledFromConfig() ==> false|#]

[#|2008-03-12T13:47:16.343+0100|INFO|sun-appserver9.1|javax.enterprise.system.stream.out|_ThreadID=14;_ThreadName=Finalizer;|
Finalizer, called close()|#]

[#|2008-03-12T13:47:16.343+0100|INFO|sun-appserver9.1|javax.enterprise.system.stream.out|_ThreadID=14;_ThreadName=Finalizer;|
Finalizer, called closeInternal(true)|#]

[#|2008-03-12T13:47:16.343+0100|INFO|sun-appserver9.1|javax.enterprise.system.stream.out|_ThreadID=14;_ThreadName=Finalizer;|
Finalizer|#]

[#|2008-03-12T13:47:16.343+0100|INFO|sun-appserver9.1|javax.enterprise.system.stream.out|_ThreadID=14;_ThreadName=Finalizer;|, SEND TLSv1 ALERT: |#]

[#|2008-03-12T13:47:16.343+0100|INFO|sun-appserver9.1|javax.enterprise.system.stream.out|_ThreadID=14;_ThreadName=Finalizer;|warning, |#]

[#|2008-03-12T13:47:16.343+0100|INFO|sun-appserver9.1|javax.enterprise.system.stream.out|_ThreadID=14;_ThreadName=Finalizer;|description = close_notify|#]

[#|2008-03-12T13:47:16.343+0100|INFO|sun-appserver9.1|javax.enterprise.system.stream.out|_ThreadID=14;_ThreadName=Finalizer;|
Finalizer, WRITE: TLSv1 Alert, length = 2|#]

[#|2008-03-12T13:47:17.031+0100|INFO|sun-appserver9.1|javax.enterprise.system.core.transaction|_ThreadID=10;_ThreadName=main;3700;|JTS5014: Recoverable JTS instance, serverId = [3700]|#]

[#|2008-03-12T13:47:17.109+0100|INFO|sun-appserver9.1|javax.enterprise.system.core|_ThreadID=10;_ThreadName=main;|About to load the system app: MEjbApp|#]

[#|2008-03-12T13:47:17.750+0100|INFO|sun-appserver9.1|javax.enterprise.system.stream.out|_ThreadID=14;_ThreadName=Finalizer;|
Finalizer, called close()|#]

[#|2008-03-12T13:47:17.750+0100|INFO|sun-appserver9.1|javax.enterprise.system.stream.out|_ThreadID=14;_ThreadName=Finalizer;|
Finalizer, called closeInternal(true)|#]

[#|2008-03-12T13:47:17.750+0100|INFO|sun-appserver9.1|javax.enterprise.system.stream.out|_ThreadID=14;_ThreadName=Finalizer;|
Finalizer|#]

[#|2008-03-12T13:47:17.750+0100|INFO|sun-appserver9.1|javax.enterprise.system.stream.out|_ThreadID=14;_ThreadName=Finalizer;|, SEND TLSv1 ALERT: |#]

[#|2008-03-12T13:47:17.750+0100|INFO|sun-appserver9.1|javax.enterprise.system.stream.out|_ThreadID=14;_ThreadName=Finalizer;|warning, |#]

[#|2008-03-12T13:47:17.750+0100|INFO|sun-appserver9.1|javax.enterprise.system.stream.out|_ThreadID=14;_ThreadName=Finalizer;|description = close_notify|#]

[#|2008-03-12T13:47:17.750+0100|INFO|sun-appserver9.1|javax.enterprise.system.stream.out|_ThreadID=14;_ThreadName=Finalizer;|
Finalizer, WRITE: TLSv1 Alert, length = 2|#]
[/i]


[b]When the login window is shown but before confirming credentials (using button OK) the log shows these 'remarkable' entries:[/b][i]
:
:
:
[#|2008-03-12T13:52:39.703+0100|INFO|sun-appserver9.1|javax.enterprise.system.stream.out|_ThreadID=16;_ThreadName=p: thread-pool-1; w: 7;|
p: thread-pool-1; w: 7, READ: [b]SSL v2[/b], contentType = Handshake, translated length = 73|#]
:
:
:
[#|2008-03-12T13:52:39.734+0100|INFO|sun-appserver9.1|javax.enterprise.system.stream.out|_ThreadID=16;_ThreadName=p: thread-pool-1; w: 7;|
p: thread-pool-1; w: 7, WRITE: TLSv1 Handshake, length = 790|#]

[#|2008-03-12T13:52:39.750+0100|INFO|sun-appserver9.1|javax.enterprise.system.stream.out|_ThreadID=16;_ThreadName=p: thread-pool-1; w: 7;|
p: thread-pool-1; w: 7, READ: TLSv1 Alert, length = 2|#]

[#|2008-03-12T13:52:39.750+0100|INFO|sun-appserver9.1|javax.enterprise.system.stream.out|_ThreadID=16;_ThreadName=p: thread-pool-1; w: 7;|
p: thread-pool-1; w: 7|#]

[#|2008-03-12T13:52:39.750+0100|INFO|sun-appserver9.1|javax.enterprise.system.stream.out|_ThreadID=16;_ThreadName=p: thread-pool-1; w: 7;|, RECV TLSv1 ALERT: |#]

[#|2008-03-12T13:52:39.750+0100|INFO|sun-appserver9.1|javax.enterprise.system.stream.out|_ThreadID=16;_ThreadName=p: thread-pool-1; w: 7;|fatal, |#]

[#|2008-03-12T13:52:39.750+0100|INFO|sun-appserver9.1|javax.enterprise.system.stream.out|_ThreadID=16;_ThreadName=p: thread-pool-1; w: 7;|internal_error|#]

[#|2008-03-12T13:52:39.750+0100|INFO|sun-appserver9.1|javax.enterprise.system.stream.out|_ThreadID=16;_ThreadName=p: thread-pool-1; w: 7;|
p: thread-pool-1; w: 7, called closeSocket()|#]

[#|2008-03-12T13:52:39.750+0100|INFO|sun-appserver9.1|javax.enterprise.system.stream.out|_ThreadID=16;_ThreadName=p: thread-pool-1; w: 7;|
p: thread-pool-1; w: 7, handling exception: javax.net.ssl.SSLException: Received fatal alert: internal_error|#]

[#|2008-03-12T13:52:39.750+0100|INFO|sun-appserver9.1|javax.enterprise.system.stream.out|_ThreadID=16;_ThreadName=p: thread-pool-1; w: 7;|
p: thread-pool-1; w: 7, called close()|#]

[#|2008-03-12T13:52:39.750+0100|INFO|sun-appserver9.1|javax.enterprise.system.stream.out|_ThreadID=16;_ThreadName=p: thread-pool-1; w: 7;|
p: thread-pool-1; w: 7, called closeInternal(true)|#]

[#|2008-03-12T13:52:39.750+0100|WARNING|sun-appserver9.1|javax.enterprise.resource.corba.ee._CORBA_.rpc.transport|_ThreadID=16;_ThreadName=p: thread-pool-1; w: 7;Thread[p: thread-pool-1; w: 7,5,main];org.omg.CORBA.COMM_FAILURE: vmcid: SUN minor code: 203 completed: No;_RequestID=acb3642c-5d94-4027-ae79-b09e2f4d1fc5;|"IOP00710311: (INTERNAL) Worker thread Thread[p: thread-pool-1; w: 7,5,main] caught throwable org.omg.CORBA.COMM_FAILURE: vmcid: SUN minor code: 203 completed: No while executing work."
org.omg.CORBA.INTERNAL: vmcid: SUN minor code: 311 completed: No
        at com.sun.corba.ee.impl.logging.ORBUtilSystemException.workerThreadDoWorkThrowable(ORBUtilSystemException.java:7706)
        at com.sun.corba.ee.impl.logging.ORBUtilSystemException.workerThreadDoWorkThrowable(ORBUtilSystemException.java:7730)
        at com.sun.corba.ee.impl.orbutil.threadpool.ThreadPoolImpl$WorkerThread.run(ThreadPoolImpl.java:558)
|#]
[/i]

When reading the logfile up to the login window being shown, it looks to me that SSL is succeeding because in the logfile there are lines about:
a trusted certificate being found,
Client key exchange,
connection keygen,
Client MAC write secret and Server MAC write secret,
client write and server write key
and a Finished occurs.

But at the end of this part things already seem to have gone wrong, because there's already a fatal internal error reported including a socketClose.

One general thing I find strange is that it looks like the server is doing the SSL stuff repeatedly.
Maybe it it just looks to be so or maybe it's normal (and can be explained) but to me - being a newbee and not familiar with the servers internal behavior - this looks somewhat like an overload of happenings...

To give you guys the complete picture of the things happening from startup until the login window is shown, I've attached that part of the server.log.

I also wondered if my problem could be related to the stuff I'm using:
WinXP Pro
client and server both on same system.
Server 9.1_1
Jre 1.6.0_4
Eclipse 3.3
GlassFish V2 Plugin for Eclipse

I hope not but .... ?

ps.
I did not alter any server parameters for ORB and the ORB-listeners (in fact I did not alter any server parameter whatsoever).
Nor did I specify any security options in the server sun-acc.xml or did I modify any other xml/properties file of the server.
Maybe I should have. If so, can you tell me what I should do where?

I really hope you gurus will be able to assist me to a glorious end.

Anyway, thanks in advance for the response.

Bart.
[Message sent by forum member 'bertusdotcom' (bertusdotcom)]

http://forums.java.net/jive/thread.jspa?messageID=263554