ICAT test.py fails...

[Milan Prica]

Dear all,

I have already talked with Tom during the very nice ICAT Workshop at STFC about this
problem, but I still cannot find what's wrong with my installation. (Initially i forgot to add
users in passwd table, but after adding some the error did not change.)

Sorry for the longish mail, but hopefully all the details below will help to spot the problem.

Please note, the host icat4a is not visible from outside the Elettra network.

0)

Host:

CentOS release 6.2
2.6.32-220.4.1.el6.x86_64

java version "1.6.0_30"
  Java(TM) SE Runtime Environment (build 1.6.0_30-b12)
  Java HotSpot(TM) 64-Bit Server VM (build 20.5-b03, mixed mode)

ojdbc6.jar (copied in glassfish/domains/domain1/lib/.)
oracle-xe-11.2.0-1.0.x86_64
glassfish-3.1.2.2-unix

All the installation has been done from scratch (oracle-xe, glassfish...)


1)

I have deployed ICAT in Glassfish with db plugin:

[glassfish3@icat4a icat.ear.config]$ asadmin list-applications
authn_db.ear-1.0.0  <ear, ejb>              
icat.ear-4.2.1      <ear, ejb, webservices>


2)

ICAT is configured to use db auth.

[glassfish3@icat4a ~]$ cat glassfish3/glassfish/domains/domain1/config/icat.properties
# Real comments in this file are marked with '#' whereas commented out lines
# are marked with '!'

# The lifetime of a session
lifetimeMinutes 120

# Provide CRUD access to authz tables
rootUserNames root icat icatuser

# Desired authentication plugin mnemonics
authn.list db
!authn.list ldap

# JNDI for each plugin
authn.db.jndi  java:global/authn_db.ear-1.0.0/authn_db.ejb-1.0.0/DB_Authenticator
#from glassfish server.log: java:global/authn_db.ear-1.0.0/authn_db.ejb-1.0.0/DB_Authenticator, java:global/authn_db.ear-1.0.0/authn_db.ejb-1.0.0/DB_Authenticator!org.icatproject.authentication.Authenticator
!authn.ldap.jndi java:global/authn_ldap.ear-1.0.0/authn_ldap.ejb-1.0.0/LDAP_Authenticator


authn_db.properties is in the same directory but everything is commented out.


3)

I have added users in PASSWD table using the sqlplus:

sqlplus icat/myicatpasswd@localhost

SQL> select * from passwd;

USERNAME
--------------------------------------------------------------------------------
ENCODEDPASSWORD
--------------------------------------------------------------------------------
bob
bobspasswd


4)

Glassfish is up and running, I can see the icat wsdl at the following address:

https://icat4a.esce.elettra.trieste.it:8181/ICATService/ICAT?wsdl



But when I run the test.py I always get the following error: (I have added some additional printouts for debugging.)

The error happens in the follwing line: sessionId = service.login(plugin, credentials)
(Or as it was originally invoked: sessionId = service.login(plugin, credentials,) )

[glassfish3@icat4a icat.ear.config]$ ./test.py icat4a.esce.elettra.trieste.it 8181 db username bob password bobspasswd
plugin: db
Service URL: https://icat4a.esce.elettra.trieste.it:8181/ICATService/ICAT?wsdl
entry >> username : bob
credentials.entry.size = 1
entry >> password : bobspasswd
credentials.entry.size = 2
Try to login...
Traceback (most recent call last):
  File "./test.py", line 35, in <module>
    sessionId = service.login(plugin, credentials)
  File "/usr/lib/python2.6/site-packages/suds/client.py", line 542, in __call__
    return client.invoke(args, kwargs)
  File "/usr/lib/python2.6/site-packages/suds/client.py", line 602, in invoke
    result = self.send(soapenv)
  File "/usr/lib/python2.6/site-packages/suds/client.py", line 657, in send
    result = self.failed(binding, e)
  File "/usr/lib/python2.6/site-packages/suds/client.py", line 712, in failed
    r, p = binding.get_fault(reply)
  File "/usr/lib/python2.6/site-packages/suds/bindings/binding.py", line 265, in get_fault
    raise WebFault(p, faultroot)
suds.WebFault: Server raised fault: 'javax.ejb.EJBException: javax.ejb.CreateException: Could not create stateless EJB'


Any suggestion is most welcome. 

Thanks!

         Milan

[Steve Fisher]

Milan,

Do you have a auth_db.log file in the log directory - and if so what
does it say?

Steve

> --
> http://groups.google.com/group/icat-developers

[Milan Prica]

No, I only have server.log.

Milan

> --
> http://groups.google.com/group/icat-developers

--
http://groups.google.com/group/icat-developers

[Steve Fisher]

Sorry for the delay I am trying to come up with a systematic way to
debug an ICAT installation - maybe the test.py will become a bit
smarter

Steve

> --
> http://groups.google.com/group/icat-developers

[Steve Fisher]

Please try the following:

in the log directory:

tail -f icat.log

then go the admin web page for glassfish, find the icat.ear-4.2.1 line
and click the reload link on that line

there should be no change in the log

then in another window run the test.py. This should trigger the
reinitialisation of ICAT. In my case it reports:

2012-10-04 14:32:42,248 [http-thread-pool-8181(1)] INFO
BeanManagerBean - Loaded log4j properties from : log4j.properties and
will watch it.
2012-10-04 14:32:42,311 [http-thread-pool-8181(1)] DEBUG
PropertyHandler - Found Authenticator: class
org.icatproject.authentication._Authenticator_Wrapper
org.icatproject.authentication._Authenticator_Wrapper@96cb6b29
2012-10-04 14:32:42,319 [http-thread-pool-8181(1)] DEBUG
PropertyHandler - Found Authenticator: class
org.icatproject.authentication._Authenticator_Wrapper
org.icatproject.authentication._Authenticator_Wrapper@96cb6b29
2012-10-04 14:32:42,359 [http-thread-pool-8181(1)] DEBUG BeanManager -
Session 53a19eb6-4260-4d61-9211-fabfbe2bdfad persisted.
2012-10-04 14:32:42,360 [http-thread-pool-8181(1)] DEBUG ICAT - Method
org.icatproject.exposed.ICAT.login() took 0.196s to execute
2012-10-04 14:32:42,443 [http-thread-pool-8181(2)] DEBUG ICAT -
Invoking org.icatproject.exposed.ICAT.search()
2012-10-04 14:32:42,451 [http-thread-pool-8181(2)] DEBUG BeanManager -
user: CIC is associated with: 53a19eb6-4260-4d61-9211-fabfbe2bdfad
2012-10-04 14:32:42,453 [http-thread-pool-8181(2)] DEBUG BeanManager -
CIC searches for Group[name='annoying animals']
...


You will note that it found the two authenticators which I have
configured - what are the first few lines that appear for you

the authn_db.log was then populated - which you tell me is empty for you


Steve

[Milan Prica]

Hi Steve,

what i get in icat.log is:

2012-10-04 15:55:43,652 [http-thread-pool-8181(4)] DEBUG ICAT - Invoking org.icatproject.exposed.ICAT.login()
2012-10-04 15:55:43,661 [http-thread-pool-8181(4)] INFO  BeanManagerBean - Loaded log4j properties from : log4j.properties and will watch it.
2012-10-04 15:55:43,703 [http-thread-pool-8181(4)] DEBUG ICAT - Method org.icatproject.exposed.ICAT.login() took 0.051s to execute

Nothing else.

Server log, same as before, a very long stack trace with the final cause:

Caused by: java.lang.IllegalStateException: class javax.naming.NamingException Lookup failed for 'java:global/authn_db.ear-1.0.0/authn_db.ejb-1.0.0/DB_Authenticator ' in SerialContext[myEnv={java.naming.factory.initial=com.sun.enterprise.naming.impl.SerialInitContextFactory, java.naming.factory.state=com.sun.corba.ee.impl.presentation.rmi.JNDIStateFactoryImpl, java.naming.factory.url.pkgs=com.sun.enterprise.naming}
    at org.icatproject.core.PropertyHandler.<init>(PropertyHandler.java:85)

And test.py response:

suds.WebFault: Server raised fault: 'javax.ejb.EJBException: javax.ejb.CreateException: Could not create stateless EJB'

I'm going now to the icat telco...

Thanks,

       milan

Steve

--
http://groups.google.com/group/icat-developers

[Steve Fisher]

Milan,

I am somewhat mystified by this. Which version and build of glassfish
is reported when you click on "About..." at the top of the glassfish
admin home page?

Steve

> --
> http://groups.google.com/group/icat-developers

[Milan Prica]

Hi Steve,

It's a:

GlassFish Server Open Source Edition 3.1.2.2 (build 5)


Milan

> --
> http://groups.google.com/group/icat-developers

--
http://groups.google.com/group/icat-developers

[Steve Fisher]

I am going to build a copy of the ICAT ear file with more diagnostics.
I will send this directly to you and not to the list. Once the issue
is resolved I will post to the list.

Steve

> --
> http://groups.google.com/group/icat-developers

[Milan Prica]

Splendid, thanks.

Milan

--
http://groups.google.com/group/icat-developers

[Steve Fisher]

Could you send me your icat.properties as an attachment. Mail can add
line breaks.

Steve

On 3 October 2012 13:51, Milan Prica <milan...@gmail.com> wrote:

> --
> http://groups.google.com/group/icat-developers

[Milan Prica]

Sure, here it comes.

Thanks, Milan

> --
> http://groups.google.com/group/icat-developers

--
http://groups.google.com/group/icat-developers

[Steve Fisher]

Now I see the problem - at last.

You picked up the value:

authn.db.jndi java:global/authn_db.ear-1.0.0/authn_db.ejb-1.0.0/DB_Authenticator,
java:global/authn_db.ear-1.0.0/authn_db.ejb-1.0.0/DB_Authenticator!org.icatproject.authentication.Authenticator

from the server log. In fact these are two possible jndi names
separated by a comma

get rid of the comma and everything after it to give:

authn.db.jndi java:global/authn_db.ear-1.0.0/authn_db.ejb-1.0.0/DB_Authenticator

and I hope it will work

Steve

> --
> http://groups.google.com/group/icat-developers

[Milan Prica]

Habemus ICAT!!

Thanks for you patience Steve.
I corrected now my both installations and finally saw the "Login, search, create, delete and logout operations were all successful." message.

Actually, I did try that before on my own (still had that setting on my second installation) and it failed.
However, I had a single trailing whitespace before the end-of-line. (And it is sufficient to create the failure we saw.)

Best,

           Milan

--
http://groups.google.com/group/icat-developers

[Steve Fisher]

Milan,

That is very good news. For the next release I will trim property values to avoid this.
I will also document the fact that the log file displays multiple portable jndi names and you must choose just one!

Steve

--
http://groups.google.com/group/icat-developers