non-JRMP server at remote endpoint

On a server with oracle 10g and JChem Cartridge 5.3.5 that used to work we are getting the following error:

ORA-29532: Java call terminated by uncaught Java exception: java.lang.Exception: Problem connecting to JChemServer: rmi://localhost:1099: non-JRMP server at remote endpoint
ORA-06512: at "JCHEM.JCHEM_CORE_PKG", line 36
ORA-06512: at "JCHEM.JCHEM_CORE_PKG", line 157

Any ideas?

many thanks

Ian

Hi Ian,

Did you check what is listening at 1099? A shell script like this could help:

#!/bin/bash

netstat -untap 2>/dev/null | awk '

/:'$1' .*LISTEN.*/ {

    print $4;

    pid = substr($7,0,length($7)-5);

    system("ls -l /proc/" pid "/cwd")}

'

<script> <port>

output is:

:::1099
lrwxrwxrwx 1 jchem jchem 0 Jun  8 15:25 /proc/4527/cwd -> /apps/chemaxon/jchem/5.3.5/cartridge

so apparently the cartridge is running on port 1099 (this was directly after a reboot)

thanks

ian

The Oracle server was rebooted, I assume... Did you also restart the JChem Cartridge server -- as well as all client sessions using JChem Cartridge?

Thanks

Peter

yes, we rebooted the virtual server (including oracle), started the jchem server and tried running a simple query:

select JCHEM.JCHEM_CORE_PKG.GETENVIRONMENT() from dual

*

Error at line 1

ORA-29532: Java call terminated by uncaught Java exception: java.lang.Exception: Problem connecting to JChemServer: rmi://localhost:1099: non-JRMP server at remote endpoint

ORA-06512: at "JCHEM.JCHEM_CORE_PKG", line 36

ORA-06512: at "JCHEM.JCHEM_CORE_PKG", line 157

Ian

You tried to restart the JChem Cartridge server after you started observing this problem, I assume, and it didn't help...

Does the JChem Cartridge server appear to start up without problem?

When you stop the JChem Cartridge server, you can see that nobody is listening at 1099 (netstat -untap), correct?

Peter

Yes we have restarted JChem server multiple times (and rebooted the whole machine once)

JChem Cartridge appears to start up fine:

+ /usr/java/jdk1.6.0_11/bin/java -Djava.util.logging.config.class=chemaxon.jchem.cartridge.util.LoggingConfigurator -Dchemaxon.jchem.cartridge.config.file=conf/jcart.properties -Djava.awt.headless=true -classpath ./../lib/jchem.jar -XX:-OmitStackTraceInFastThrow chemaxon.jchem.cartridge.server.Bootstrapper start
INFO: Server control process started
INFO: Using classpath: /apps/chemaxon/jchem/5.3.5/lib/jchem.jar
INFO: Server process start-ed.
INFO: Cache id set to JCC1
INFO: Listening on network interface 0.0.0.0/0.0.0.0 at port 1099...
AdminImpl: shutdown called...
INFO: shutdown called
Exiting...
INFO:
Shutting down...
 

Can we put extra logging on this output?

Once stopped, nothing is on 1099 according to your little script.

Its strange that it has started on two machines (a DEV and TEST environment) but not on the LIVE environment...

cheers

Ian

With logging set to finest:

FINE: main: (port 0) create server socket
FINEST: FINER: main: creating server socket on [localhost:0]

FINER: main: creating server socket on [localhost:0]
FINEST: FINE: main: default port for server socket factory null and client socket factory null set to 6094

FINE: main: default port for server socket factory null and client socket factory null set to 6094
FINEST: FINE: RMI TCP Accept-0: listening on port 6094

FINE: RMI TCP Accept-0: listening on port 6094
FINEST: FINER: main: strongRef = sun.rmi.transport.DGCImpl@6115273a

FINER: main: strongRef = sun.rmi.transport.DGCImpl@6115273a
FINEST: FINER: main: add object [0:0:0, 2]

FINER: main: add object [0:0:0, 2]
FINEST: FINER: main: add object [-6f62f27f:137ccb5d1de:-7fff, -5317439951930587182]

FINER: main: add object [-6f62f27f:137ccb5d1de:-7fff, -5317439951930587182]
FINEST: FINER: main: string used for method hash: "get(Ljava/lang/String;)Ljava/rmi/Remote;"

FINER: main: string used for method hash: "get(Ljava/lang/String;)Ljava/rmi/Remote;"
FINEST: FINER: main: string used for method hash: "getTunnelPort()I"

FINER: main: string used for method hash: "getTunnelPort()I"
FINEST: FINER: main: string used for method hash: "getLocale()[Ljava/lang/String;"

FINER: main: string used for method hash: "getLocale()[Ljava/lang/String;"
FINEST: FINER: main: string used for method hash: "checkVersion(Ljava/lang/String;)V"

FINER: main: string used for method hash: "checkVersion(Ljava/lang/String;)V"
FINEST: FINER: main: string used for method hash: "getEnvironment(Ljava/lang/String;)Ljava/lang/String;"

FINER: main: string used for method hash: "getEnvironment(Ljava/lang/String;)Ljava/lang/String;"
FINEST: FINER: main: string used for method hash: "getTunnelSocketTimeout()I"

FINER: main: string used for method hash: "getTunnelSocketTimeout()I"
FINEST: FINE: Looking in /apps/chemaxon/jchem/5.3.5/cartridge/licenses for license files...

FINE: Looking in /apps/chemaxon/jchem/5.3.5/cartridge/licenses for license files...
FINEST: FINE: Processing file /apps/chemaxon/jchem/5.3.5/cartridge/licenses/license.cxl

FINE: Processing file /apps/chemaxon/jchem/5.3.5/cartridge/licenses/license.cxl
FINEST: CONFIG: Searching for license file given with Java system property: chemaxon.license.url

CONFIG: Searching for license file given with Java system property: chemaxon.license.url
FINEST: CONFIG: Searching for license file given with environment variable: CHEMAXON_LICENSE_URL

CONFIG: Searching for license file given with environment variable: CHEMAXON_LICENSE_URL
FINEST: CONFIG: Reading license file from user home failed: /apps/chemaxon/jchem/.chemaxon/license.cxl

CONFIG: Reading license file from user home failed: /apps/chemaxon/jchem/.chemaxon/license.cxl
FINEST: CONFIG: Setting license file: /apps/chemaxon/jchem/5.3.5/cartridge/licenses/license.cxl

CONFIG: Setting license file: /apps/chemaxon/jchem/5.3.5/cartridge/licenses/license.cxl
FINEST: FINE: Creating FileInputStream from /apps/chemaxon/jchem/5.3.5/cartridge/licenses/license.cxl

FINE: Creating FileInputStream from /apps/chemaxon/jchem/5.3.5/cartridge/licenses/license.cxl
FINEST: FINE: Processing file /apps/chemaxon/jchem/5.3.5/cartridge/licenses/license_2010.cxl.old

FINE: Processing file /apps/chemaxon/jchem/5.3.5/cartridge/licenses/license_2010.cxl.old
FINEST: CONFIG: Setting license file: /apps/chemaxon/jchem/5.3.5/cartridge/licenses/license_2010.cxl.old

CONFIG: Setting license file: /apps/chemaxon/jchem/5.3.5/cartridge/licenses/license_2010.cxl.old
FINEST: FINE: Creating FileInputStream from /apps/chemaxon/jchem/5.3.5/cartridge/licenses/license_2010.cxl.old

FINE: Creating FileInputStream from /apps/chemaxon/jchem/5.3.5/cartridge/licenses/license_2010.cxl.old
FINEST: INFO: Listening on network interface 0.0.0.0/0.0.0.0 at port 1099...

INFO: Listening on network interface 0.0.0.0/0.0.0.0 at port 1099...

Thank you for this, Ian!

In

+ /usr/java/jdk1.6.0_11/bin/java -Djava.util.logging.config.class=chemaxon.jchem.cartridge.util.LoggingConfigurator -Dchemaxon.jchem.cartridge.config.file=conf/jcart.properties -Djava.awt.headless=true -classpath ./../lib/jchem.jar -XX:-OmitStackTraceInFastThrow chemaxon.jchem.cartridge.server.Bootstrapper start
INFO: Server control process started
INFO: Using classpath: /apps/chemaxon/jchem/5.3.5/lib/jchem.jar
INFO: Server process start-ed.
INFO: Cache id set to JCC1
INFO: Listening on network interface 0.0.0.0/0.0.0.0 at port 1099...
AdminImpl: shutdown called...
INFO: shutdown called
Exiting...
INFO:
Shutting down...

The shutdown was intentional, correct?

Peter

yes it was to test that the port was freed...

Can you telnet to the server:

[pkovacs@pkovacs [trunk]/.*/cartridge]$ telnet localhost 1099

Trying 127.0.0.1...

Connected to localhost.localdomain (127.0.0.1).

Escape character is '^]'.

?

Peter

Connection closed by foreign host.

Retested with JChem 5.3.5:

[pkovacs@pkovacs [trunk]/.*/cartridge]$ telnet localhost 1099
Trying 127.0.0.1...
Connected to localhost.localdomain (127.0.0.1).
Escape character is '^]'.
��sr4chemaxon.jchem.cartridge.rmi.impl.DirectoryImpl_Stubxrjava.rmi.server.RemoteStub���Éďż˝exrjava.rmi.server.RemoteObjectďż˝a��a3xpw2
UnicastRef      localhostdďż˝j|)$(ďż˝\FR��7��uËxConnection closed by foreign host.

chemaxon.jchem.cartridge.rmi.impl.DirectoryImpl_Stubxrjava.rmi.server.RemoteStub

a3xpw2
7̵ÑÞxConnection closed by foreign host.
PuTTYuk-abi-sdb21 jchem $ PuTTY

is everything I get back (it clears the screen in putty before I get this)

I see, so this is a Windows VM.

Anything changed in network configuration? Microsoft loopback adapter installed? ...system32/etc/hosts file modified? Firewall turned on (or turned off)?

Peter

Anything changed in Oracle or Windows? Patches added or removed?

Peter

No this is a linux machine (I am connecting to it from a windows machine via Putty Telnet client

Ian

The error message complains about "localhost", which means that Oracle is supposed to be running on this same Linux host. Is this correct?

If so, what is the output of telneting from the same linux host into the JChem Cartridge server?

Thanks

Peter

The result is what I showed above.  I am using Putty on windows to ssh onto the server where the jchem cartridge and oracle database are installed  and am running all the commands from there.

cheers

Ian

Thank you, Ian, for this information!

Please, could you execute the following command in the jchem/cartridge directory on the affected server

./ping-jcserver.sh localhost:1099; echo $?

and post the output?

Thanks

Peter

I should have been more precise in my previous post:

Please, could you execute the following command ... with the JChem Server running.

Thanks

Peter

here you go.... doesn't look good!

uk-abi-sdb17 jchem $ sh ./ping-jcserver.sh localhost:1099; echo $?
Exception in thread "main" java.lang.NoClassDefFoundError: chemaxon/jchem/cartridge/install/JChemServerPinger
Caused by: java.lang.ClassNotFoundException: chemaxon.jchem.cartridge.install.JChemServerPinger
        at java.net.URLClassLoader$1.run(URLClassLoader.java:200)
        at java.security.AccessController.doPrivileged(Native Method)
        at java.net.URLClassLoader.findClass(URLClassLoader.java:188)
        at java.lang.ClassLoader.loadClass(ClassLoader.java:307)
        at sun.misc.Launcher$AppClassLoader.loadClass(Launcher.java:301)
        at java.lang.ClassLoader.loadClass(ClassLoader.java:252)
        at java.lang.ClassLoader.loadClassInternal(ClassLoader.java:320)
Could not find the main class: chemaxon.jchem.cartridge.install.JChemServerPinger.  Program will exit.
1

ok just looked at the code for the ping script and it was point to your home directory Peter

changed it to point at the local jchem.jar and get:

uk-abi-sdb17 jchem $ sh ./ping-jcserver.sh localhost:1099; echo $?
Trying localhost:1099
Jun 11, 2012 2:27:59 PM chemaxon.jchem.cartridge.install.InstallUtil checkJChemServer
INFO: Checking JChem Server at localhost:1099...
0

I presume the 0 means that it cannot connect? But the server appears to be working...

jchem     6142     1  0 Jun07 ?        00:00:00 sh server.sh start
jchem     6145  6142  0 Jun07 ?        00:00:01 /usr/java/jdk1.6.0_11/bin/java -Djava.util.logging.config.class=chemaxon.jchem.cartridge.util.LoggingConfigurator -Dchemaxon.jchem.cartridge.config.file=conf/jcart.properties -Djava.awt.hea
jchem     6156  6145  0 Jun07 ?        00:00:01 /usr/java/jdk1.6.0_11/bin/java -server -Xmx950m -XX:-OmitStackTraceInFastThrow -Dchemaxon.jchem.cartridge.config.file=/apps/chemaxon/jchem/5.3.5/cartridge/conf/jcart.properties -Djava.util.

Ian

Many thanks, Ian, for looking more closely at the script and sorry for this little inconvenience! (The script in more recent JChem versions has been changed to include the path in relative form.)

The exit value "0" of the pinger shows that the JChem Server end of the installation is OK. (The script includes in comment the meaning of the possible exit values from 0 through 4 -- the value "0" meaning "OK"/"Success" by convention.) It is likely then that there was a change in the environment which affects the Oracle end. I am trying to come up with something to help find out more...

Peter

could we just try reinstalling or upgrading the cartridge (to the same version - to a later one will need a lot more testing!!)?

Yes, both re-installing and upgrading to the same version are among the options.

You can also try first to reconfigure the port first from 1099 to something else (1100?) to see if it makes any difference. (You have to set the jchem.server.port property in the cartridge/conf/jcart.properties files and the rmi.server.1 property in the jc_idx_property table of the JChem owner of the affected instance. And you'll have to call

call dbms_java.grant_permission('<jchem-owner-or-jchem-role>', 'SYS:java.net.SocketPermission', 'localhost:1100', 'resolve,connect');

as SYSTEM once for the JChem Cartridge "owner" and once for the role.

) 

Based on my experience and some googling, this error messages is generated by RMI clients (JCC's Oracle-resident part is also an RMI client), if they hit at the configured network location a JNP server (instead of an RMI server) which JNP server is almost always running as part of a JBoss installation. Does this ring any bells to you?

Peter

just tried changing the port and no success I am afraid.  I'll try upgrading and see what happens

we don't use JBoss here, and certainly wouldn't install a app server on a db machine anyway...

i'll keep trying!

thanks for all your help!

Ian

Hi Peter,

We still have the problem on 2 servers (test and dev databases).

Yesterday it started happening on a live server, however a reboot fixed that one.  I have tried updating teh installation and that has had no effect.  I am promised by IT that nothing has changed on these servers for a long time. 

Any more ideas?

thanks Ian

Preliminary results of an off-line investigation of the issue:

• Upgrading the JCC instance to the same version didn't solve the problem.


• Removing and re-installing the same JCC version solved the problem in the case of one of the affected instances.


• Reviewing the Oracle-resident parts of the second affected instance (not yet upgraded, reinstalled), we found that some of the stored procedures and (most of) the Java classes loaded into Oracle were in an invalid state. Recompilation of these database objects didn't solve the problem. Re-installation of this second JCC instance is also likely to be needed.

The problem seems to be related to the fact that the affected VMs hasn't been used for an extended period of time.

Peter