users@glassfish.java.net

Re: EJBContext: thread safe?

From: Laird Nelson <ljnelson_at_gmail.com>
Date: Fri, 19 Aug 2011 10:31:33 -0400

On Thu, Aug 18, 2011 at 5:01 PM, Laird Nelson <ljnelson_at_gmail.com> wrote:

> I am doing something along the lines of
> http://www.mindbug.org/2008/04/automatic-tracing-of-entity-changes.html.
> However, I want to ensure I am careful to be thread safe.
>

Independent of thread safety, now I'm wondering if this is possible on
Glassfish. It certainly looks like it should be.

Here is the relevant part of my code--this is the entity listener that is
responsible for filling in details about who created and updated an entity,
when. I'll comment it inline. The gist is that I am seeing a
NamingException on looking up java:comp/EJBContext that is caused by an
IllegalStateException that seems to indicate that the EJBContext cannot be
looked up from a servlet. I don't really know why this is, since this
entity listener is only ever called by an EJB, and the exception stack shows
it being invoked from inside the call stack associated with a local EJB, as
I would expect. Here's the code (apologies in advance for folks reading
this on the forums and not on the users_at_glassfish.java.net list as the forum
software will lose all formatting):

public class PrincipalAuditor {

  private static final Object lock;

  private static final Object context;

  static {
    lock = new byte[0];
    Object temp = null;
    try {
      temp = new InitialContext();
    } catch (final RuntimeException kaboom) {
      temp = kaboom;
    } catch (final NamingException kaboom) {
      temp = kaboom;
    } finally {
      context = temp;
    }
  }

  protected final Logger logger;

  public PrincipalAuditor() {
    super();
    assert context != null;
    final Logger logger = this.createLogger();
    if (logger == null) {
      this.logger = Logger.getLogger(this.getClass().getName());
    } else {
      this.logger = logger;
    }
  }

  protected Logger createLogger() {
    return Logger.getLogger(this.getClass().getName());
  }

  @PreUpdate
  public void initializeUpdatedBy(final AbstractAuditChangeLog object) {
    if (context instanceof Throwable) {
      throw new PersistenceException((Throwable)context);
    }

    // This all works fine--context is getting set properly, so this if
block always runs:
    if (object != null && context instanceof Context) {
      Principal principal = null;
      Object ejbContext = null;
      synchronized (lock) {
        try {
          // This lookup fails with an IllegalStateException
("SERVLET_INVOCATION").
          ejbContext = ((Context)context).lookup("java:comp/EJBContext");
        } catch (final RuntimeException throwMe) {
          throw throwMe;
        } catch (final NamingException nothingThere) {
          if (this.logger.isLoggable(Level.WARNING)) {
            this.logger.logp(Level.WARNING, this.getClass().getName(),
"initializeUpdatedBy", "The lookup of java:comp/EJBContext threw a
NamingException. This may be expected.", nothingThere);
          }
        }
      }
      if (ejbContext != null) {
        final Class<?> c = ejbContext.getClass();
        assert c != null;
        try {
          // I didn't want an explicit dependency on the javax.ejb package,
so I use reflection.
          final Method getCallerPrincipalMethod =
c.getMethod("getCallerPrincipal");
          if (getCallerPrincipalMethod != null) {
            principal =
(Principal)getCallerPrincipalMethod.invoke(ejbContext);
          }
        } catch (final RuntimeException throwMe) {
          throw throwMe;
        } catch (final Exception everythingElse) {
          throw new PersistenceException(everythingElse);
        }
      }
      if (principal != null) {
        object.setUpdatedBy(principal.getName());
      }
    }
  }

So here's (part of the monstrous) stack I get in the logger's warning above
(again, apologies to forum readers for the hatchet job on the formatting the
forum software will perform):

javax.naming.NamingException: Lookup failed for 'java:comp/EJBContext' 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} [Root exception is
javax.naming.NameNotFoundException: No object bound for java:comp/EJBContext
[Root exception is java.lang.IllegalStateException: Illegal invocation type
for EJB Context : SERVLET_INVOCATION]]

      at
com.sun.enterprise.naming.impl.SerialContext.lookup(SerialContext.java:518)

      at
com.sun.enterprise.naming.impl.SerialContext.lookup(SerialContext.java:455)

      at javax.naming.InitialContext.lookup(InitialContext.java:392)

      at javax.naming.InitialContext.lookup(InitialContext.java:392)

      at
com.foobar.PrincipalAuditor.initializeUpdatedBy(PrincipalAuditor.java:76)

      at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)

      at
sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39)

      at
sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)

      at java.lang.reflect.Method.invoke(Method.java:597)

      at
org.hibernate.ejb.event.ListenerCallback.invoke(ListenerCallback.java:45)

      at
org.hibernate.ejb.event.EntityCallbackHandler.callback(EntityCallbackHandler.java:94)

      at
org.hibernate.ejb.event.EntityCallbackHandler.preUpdate(EntityCallbackHandler.java:79)

      at
org.hibernate.ejb.event.EJB3FlushEntityEventListener.invokeInterceptor(EJB3FlushEntityEventListener.java:61)

      at
org.hibernate.event.def.DefaultFlushEntityEventListener.handleInterception(DefaultFlushEntityEventListener.java:349)

      at
org.hibernate.event.def.DefaultFlushEntityEventListener.scheduleUpdate(DefaultFlushEntityEventListener.java:287)

      at
org.hibernate.event.def.DefaultFlushEntityEventListener.onFlushEntity(DefaultFlushEntityEventListener.java:155)

      at
org.hibernate.event.def.AbstractFlushingEventListener.flushEntities(AbstractFlushingEventListener.java:219)

      at
org.hibernate.event.def.AbstractFlushingEventListener.flushEverythingToExecutions(AbstractFlushingEventListener.java:99)

      at
org.hibernate.event.def.DefaultFlushEventListener.onFlush(DefaultFlushEventListener.java:50)

      at org.hibernate.impl.SessionImpl.flush(SessionImpl.java:1206)

      at org.hibernate.impl.SessionImpl.managedFlush(SessionImpl.java:375)

      at
org.hibernate.ejb.AbstractEntityManagerImpl$1.beforeCompletion(AbstractEntityManagerImpl.java:1001)

      at
com.sun.enterprise.transaction.JavaEETransactionImpl.commit(JavaEETransactionImpl.java:437)

      at
com.sun.enterprise.transaction.JavaEETransactionManagerSimplified.commit(JavaEETransactionManagerSimplified.java:867)

      at
com.sun.ejb.containers.BaseContainer.completeNewTx(BaseContainer.java:5115)

      at
com.sun.ejb.containers.BaseContainer.postInvokeTx(BaseContainer.java:4880)

      at
com.sun.ejb.containers.BaseContainer.postInvoke(BaseContainer.java:2039)

      at
com.sun.ejb.containers.BaseContainer.postInvoke(BaseContainer.java:1990)

      at
com.sun.ejb.containers.EJBLocalObjectInvocationHandler.invoke(EJBLocalObjectInvocationHandler.java:222)

      at
com.sun.ejb.containers.EJBLocalObjectInvocationHandlerDelegate.invoke(EJBLocalObjectInvocationHandlerDelegate.java:88)

      at $Proxy345.findbyUniqueId(Unknown Source) // note: this is a local
EJB invocation

I went back to the JPA specification and read (section 3.5) that the entity
listener is supposed to share the JNDI context with the EJB from which it is
invoked:

When invoked from within a Java EE environment, the callback listeners for
> an entity share the enterprise naming context of the invoking component, and
> the entity callback methods are invoked in the transaction and security
> contexts of the calling component at the time at which the callback method
> is invoked.
>

Could the problem be with the fact that the InitialContext is created so
early in the process (maybe that "locks down" what naming/security contexts
it is initialized with)? Or is this a bug?

Glassfish 3.1.

Thanks,
Laird

-- 
http://about.me/lairdnelson