WildFly error when provider's close() method is called

Hi

Short version:
UserStorageProvider implemented as Stateful EJB gets the following error when its close() method, which is annotated with @Remove, is called by Keycloak:

ERROR [org.jboss.as.ejb3] (default task-4) WFLYEJB0487: Unexpected invocation state 0

More details:
Everything still works fine and I can’t see any weird errors anywhere else but I’m not sure if it would be safe to continue using this in production.

If I remove the @Remove annotation, the error would disappear but then the EJB instances would pile up and eventually the “ejb” cache in the Infinispan reaches 60GB+ and Infinispan would gets timed out when trying to sync it on startup.

When I enabled the trace log for ejb3 module in WildFly I noticed that it happens when WildFly tries to release the lock and apparently it’s happening twice and the second one always has this error. To easily see the order of events, here is the summary of the logs until the error happens :

1:[org.jboss.as.ejb3]: Looking for stateful component instance with session id...
2:[org.jboss.as.ejb3]: Trying to acquire lock...
3:[org.jboss.as.ejb3]: Acquired lock...
4:[EmployeeUserProvider]: getUserById called for user id f:ff0d54bd-0d1c-4316-a41c-7485e39b07b7:3 and realm Internal
5:[org.jboss.as.ejb3]: Released lock...
6:[org.jboss.as.ejb3]: Calling release from synchronization interceptor...
7:[org.jboss.as.ejb3]: Released lock...
8:[org.jboss.as.ejb3]: Calling release from synchronization interceptor...
9:[org.jboss.as.ejb3]: WFLYEJB0487: Unexpected invocation state 0
  • Line 4 is the log from my own provider.

There are many calls to the EJB when a user tries to login and here is the normal order of events for them:

1:[org.jboss.as.ejb3]: Looking for stateful component instance with session id...
2:[org.jboss.as.ejb3]: Trying to acquire lock...
3:[org.jboss.as.ejb3]: Acquired lock...
4:[EmployeeUserProvider]: getUserById called for user id f:ff0d54bd-0d1c-4316-a41c-7485e39b07b7:3 and realm Internal
5:[org.jboss.as.ejb3]: Released lock...
6:[org.jboss.as.ejb3]: Calling release from synchronization interceptor...

The weird thing is that it only happens once during the login of a user even though the sequence of “acquiring and releasing lock for this ejb” appears many times before and after this error. It’s always for getUserByid method but again, the getUserById is called few times before and after that with the same order of events in the log and none of them get to this error.

I guess it should be somehow related to the way the close() method is called from Keycloak which triggers this situation when the provider is a Stateful EJB. We’re using JEE stack and the implementation is based on JPA and other stuff, so it’s not easy to just switch away from Stateful EJB.

Does anyone knows a solution or workaround for this?

The full log with all the details is:

[org.jboss.as.ejb3]: Looking for stateful component instance with session id: UUIDSessionID [d4aea8f3-769a-42b9-a9ad-1fbd770f96dd]
[org.jboss.as.ejb3]: Trying to acquire lock: org.jboss.as.ejb3.tx.OwnableReentrantLock@5f5f58b6[Locked by 0:ffffac160004:1b0c1cb7:5fb680b6:f9c] for stateful component instance: Instance of EmployeesUserProvider {UUIDSessionID [d4aea8f3-769a-42b9-a9ad-1fbd770f96dd]} during invocation: org.jboss.invocation.InterceptorContext@5b48dbb5
[org.jboss.as.ejb3]: Acquired lock: org.jboss.as.ejb3.tx.OwnableReentrantLock@5f5f58b6[Locked by 0:ffffac160004:1b0c1cb7:5fb680b6:f9c] for stateful component instance: Instance of EmployeesUserProvider {UUIDSessionID [d4aea8f3-769a-42b9-a9ad-1fbd770f96dd]} during invocation: org.jboss.invocation.InterceptorContext@5b48dbb5
[EmployeeUserProvider]: getUserById called for user id f:ff0d54bd-0d1c-4316-a41c-7485e39b07b7:3 and realm Internal
[org.jboss.as.ejb3]: Released lock: org.jboss.as.ejb3.tx.OwnableReentrantLock@5f5f58b6[Locked by 0:ffffac160004:1b0c1cb7:5fb680b6:f9c]
[org.jboss.as.ejb3]: Calling release from synchronization interceptor (#2), instance id K = UUIDSessionID [d4aea8f3-769a-42b9-a9ad-1fbd770f96dd]
[org.jboss.as.ejb3]: Released lock: org.jboss.as.ejb3.tx.OwnableReentrantLock@5f5f58b6[Locked by 0:ffffac160004:1b0c1cb7:5fb680b6:f9c]
[org.jboss.as.ejb3]: Calling release from synchronization interceptor (#2), instance id K = UUIDSessionID [d4aea8f3-769a-42b9-a9ad-1fbd770f96dd]
[org.jboss.as.ejb3]: WFLYEJB0487: Unexpected invocation state 0

Thanks

I am also getting the same error.

FYI, we only get this error when we run it inside a container in our dev/test environments. In production it’s not running on docker and there is no such error. In production we have our Keycloak installed as an overlay on top of an existing WildFly. So its standalone.xml file is different than the one in the docker. I never investigated deeper as it’s not critical for us anymore.