Jboss 7.2 root-logger 级别 DEBUG 在执行 jpa 查询时引发 ConcurrentModificationException

Question

环境：

JBoss 7.2.0
Java11
休眠 5.3.15.Final

我在从无状态 ejb 中的方法执行 jpa 查询时收到错误 ConcurrentModificationException。它一直工作到现在，不知道它会是什么。查询仅获取条件中的记录。

错误日志

13:06:24,419 ERROR [es.caib.accfor.presentation.back.security.UserPrincipalManager] (default task-1) Error UserPrincipalManager.doFilter: es.caib.accfor.business.AppException: Exception UsuarioService.trace
    at deployment.accfor2.ear.accfor-ejb.jar//es.caib.accfor.business.security.boundary.UsuariService.trace(UsuariService.java:254)
    ...
    Suppressed: javax.ejb.EJBTransactionRolledbackException: javax.transaction.RollbackException: ARJUNA016053: Could not commit transaction.
        at org.jboss.as.ejb3@7.2.0.GA-redhat-00005//org.jboss.as.ejb3.tx.CMTTxInterceptor.endTransaction(CMTTxInterceptor.java:114)
        at org.jboss.as.ejb3@7.2.0.GA-redhat-00005//org.jboss.as.ejb3.tx.CMTTxInterceptor.endTransaction(CMTTxInterceptor.java:122)
        at org.jboss.as.ejb3@7.2.0.GA-redhat-00005//org.jboss.as.ejb3.tx.CMTTxInterceptor.invokeInOurTx(CMTTxInterceptor.java:256)
        ... 106 more
    Caused by: javax.transaction.RollbackException: ARJUNA016053: Could not commit transaction.
        at org.jboss.jts//com.arjuna.ats.internal.jta.transaction.arjunacore.TransactionImple.commitAndDisassociate(TransactionImple.java:1300)
        at org.jboss.jts//com.arjuna.ats.internal.jta.transaction.arjunacore.BaseTransaction.commit(BaseTransaction.java:126)
        at org.jboss.jts.integration//com.arjuna.ats.jbossatx.BaseTransactionManagerDelegate.commit(BaseTransactionManagerDelegate.java:89)
        at org.wildfly.transaction.client@1.1.2.Final-redhat-1//org.wildfly.transaction.client.LocalTransaction.commitAndDissociate(LocalTransaction.java:77)
        at org.wildfly.transaction.client@1.1.2.Final-redhat-1//org.wildfly.transaction.client.ContextTransactionManager.commit(ContextTransactionManager.java:71)
        at org.jboss.as.ejb3@7.2.0.GA-redhat-00005//org.jboss.as.ejb3.tx.CMTTxInterceptor.endTransaction(CMTTxInterceptor.java:88)
        ... 108 more
        Suppressed: javax.transaction.RollbackException: WFTXN0061: Transaction is marked rollback-only
            ...
        Suppressed: javax.transaction.RollbackException: WFTXN0061: Transaction is marked rollback-only
            ...
    Caused by: java.util.ConcurrentModificationException
        at java.base/java.util.HashMap$HashIterator.nextNode(HashMap.java:1493)
        at java.base/java.util.HashMap$EntryIterator.next(HashMap.java:1526)
        at java.base/java.util.HashMap$EntryIterator.next(HashMap.java:1524)
        at org.hibernate@5.3.7.Final-redhat-00001//org.hibernate.internal.util.EntityPrinter.toString(EntityPrinter.java:104)
        at org.hibernate@5.3.7.Final-redhat-00001//org.hibernate.event.internal.AbstractFlushingEventListener.logFlushResults(AbstractFlushingEventListener.java:129)
        at org.hibernate@5.3.7.Final-redhat-00001//org.hibernate.event.internal.AbstractFlushingEventListener.flushEverythingToExecutions(AbstractFlushingEventListener.java:105)
        at org.hibernate@5.3.7.Final-redhat-00001//org.hibernate.event.internal.DefaultFlushEventListener.onFlush(DefaultFlushEventListener.java:38)
        at org.hibernate@5.3.7.Final-redhat-00001//org.hibernate.internal.SessionImpl.doFlush(SessionImpl.java:1454)
        at org.hibernate@5.3.7.Final-redhat-00001//org.hibernate.internal.SessionImpl.managedFlush(SessionImpl.java:511)
        at org.hibernate@5.3.7.Final-redhat-00001//org.hibernate.internal.SessionImpl.flushBeforeTransactionCompletion(SessionImpl.java:3283)
        at org.hibernate@5.3.7.Final-redhat-00001//org.hibernate.internal.SessionImpl.beforeTransactionCompletion(SessionImpl.java:2479)
        at org.hibernate@5.3.7.Final-redhat-00001//org.hibernate.engine.jdbc.internal.JdbcCoordinatorImpl.beforeTransactionCompletion(JdbcCoordinatorImpl.java:473)
        at org.hibernate@5.3.7.Final-redhat-00001//org.hibernate.resource.transaction.backend.jta.internal.JtaTransactionCoordinatorImpl.beforeCompletion(JtaTransactionCoordinatorImpl.java:352)
        at org.hibernate@5.3.7.Final-redhat-00001//org.hibernate.resource.transaction.backend.jta.internal.synchronization.SynchronizationCallbackCoordinatorNonTrackingImpl.beforeCompletion(SynchronizationCallbackCoordinatorNonTrackingImpl.java:47)
        at org.hibernate@5.3.7.Final-redhat-00001//org.hibernate.resource.transaction.backend.jta.internal.synchronization.RegisteredSynchronization.beforeCompletion(RegisteredSynchronization.java:37)
        at org.jboss.as.transactions@7.2.0.GA-redhat-00005//org.jboss.as.txn.service.internal.tsr.JCAOrderedLastSynchronizationList.beforeCompletion(JCAOrderedLastSynchronizationList.java:113)
        at org.wildfly.transaction.client@1.1.2.Final-redhat-1//org.wildfly.transaction.client.AbstractTransaction.performConsumer(AbstractTransaction.java:236)
        at org.wildfly.transaction.client@1.1.2.Final-redhat-1//org.wildfly.transaction.client.AbstractTransaction.performConsumer(AbstractTransaction.java:247)
        at org.wildfly.transaction.client@1.1.2.Final-redhat-1//org.wildfly.transaction.client.AbstractTransaction$AssociatingSynchronization.beforeCompletion(AbstractTransaction.java:292)
        at org.jboss.jts//com.arjuna.ats.internal.jta.resources.arjunacore.SynchronizationImple.beforeCompletion(SynchronizationImple.java:76)
        at org.jboss.jts//com.arjuna.ats.arjuna.coordinator.TwoPhaseCoordinator.beforeCompletion(TwoPhaseCoordinator.java:360)
        at org.jboss.jts//com.arjuna.ats.arjuna.coordinator.TwoPhaseCoordinator.end(TwoPhaseCoordinator.java:91)
        at org.jboss.jts//com.arjuna.ats.arjuna.AtomicAction.commit(AtomicAction.java:162)
        at org.jboss.jts//com.arjuna.ats.internal.jta.transaction.arjunacore.TransactionImple.commitAndDisassociate(TransactionImple.java:1288)
        ... 113 more

UserPrincipalManager(过滤器)

@WebFilter(filterName = "UserPrincipalFilter", urlPatterns = "/*")
public class UserPrincipalManager implements Filter {

    @Inject
    private UsuariServiceable usuariSvc;


    @Override
    public void doFilter(ServletRequest req, ServletResponse resp, FilterChain chain) throws java.io.IOException, ServletException {
        ...
        Usuari usuari = usuariSvc.trace(loadUserData(sReq.getUserPrincipal()));
        ...
        chain.doFilter(req, resp);
    }

用户服务

@RolesAllowed("**")
@Stateless
public class UserService {
    ...

    public Usuari trace(UserPrincipal uPrincipal) throws AppException {
       //I tried a simple db query and also get this error ConcurrentModificationException without anything else
       ...
       List<VTaula> rolNames = vTaulaSvc.findByNames(rolsToAdd); //Error by calling findByNames(HashSet<String>)
       ...
    }
}

VTaulaService

@PermitAll
@Stateless
public class VTaulaService extends BusinessService<VTaula> implements VTaulaServiceable {
    @PersistenceContext(unitName = "appPU")
    protected EntityManager eManager;
    ...
    public List<VTaula> findByNames(Set<String> names) throws AppException {
        List<VTaula> vTaulas;

        try {
            Query q = eManager.createNamedQuery("SELECT g FROM VTaula g WHERE g.nomCA IN (:names)");
            q.setParameter("names", names);
            vTaulas = q.getResultList();  //Error ConcurrentModificationException

        } catch (Exception e) {
            log.error("findByNomCA", e);
            throw new AppException("Error VTaula " + e, e);
        }

        return vTaulas;
    }

    ...
}

standalone.xml

...
<root-logger>
   <level name="DEBUG"/>
   <handlers>
       <handler name="CONSOLE"/>
       <handler name="FILE"/>
   </handlers>
</root-logger>
...

//Also happen with org.hibernate
 <logger category="org.hibernate">
     <level name="DEBUG"/>
 </logger>

Answer 1

问题似乎出在 root-logger 和级别 DEBUG 上，我只是将该级别恢复为 INFO，这个问题就消失了。

真正的问题似乎与休眠日志有关，但不知道具体是什么。

这是一个解决方法，但我也可以使用 DEBUG 级别。

standalone.xml

...
<root-logger>
   <level name="INFO"/>
   <handlers>
       <handler name="CONSOLE"/>
       <handler name="FILE"/>
   </handlers>
</root-logger>
...

我添加了调试级别的记录器，通过这种方式避免了 ConcurrentModificationException：

使用 CLI 添加包记录器

/subsystem=logging/logger=com.package:add(level=DEBUG)
/subsystem=logging/console-handler=CONSOLE:write-attribute(name=level,value=DEBUG)

结果 standalone.xml 记录器如下所示

standalone.xml

    <subsystem xmlns="urn:jboss:domain:logging:6.0">
        <console-handler name="CONSOLE">
            <level name="DEBUG"/>
            <formatter>
                <named-formatter name="COLOR-PATTERN"/>
            </formatter>
        </console-handler>
        <periodic-rotating-file-handler name="FILE" autoflush="true">
            <formatter>
                <named-formatter name="PATTERN"/>
            </formatter>
            <file relative-to="jboss.server.log.dir" path="server.log"/>
            <suffix value=".yyyy-MM-dd"/>
            <append value="true"/>
        </periodic-rotating-file-handler>
        <logger category="com.arjuna">
            <level name="WARN"/>
        </logger>
        <logger category="org.jboss.as.config">
            <level name="DEBUG"/>
        </logger>
        <logger category="sun.rmi">
            <level name="WARN"/>
        </logger>
        <logger category="com.package">
            <level name="DEBUG"/>
        </logger>
        <root-logger>
            <level name="INFO"/>
            <handlers>
                <handler name="CONSOLE"/>
                <handler name="FILE"/>
            </handlers>
        </root-logger>
        <formatter name="PATTERN">
            <pattern-formatter pattern="%d{yyyy-MM-dd HH:mm:ss,SSS} %-5p [%c] (%t) %s%e%n"/>
        </formatter>
        <formatter name="COLOR-PATTERN">
            <pattern-formatter pattern="%K{level}%d{HH:mm:ss,SSS} %-5p [%c] (%t) %s%e%n"/>
        </formatter>
    </subsystem>

Jboss 7.2 root-logger 级别 DEBUG 在执行 jpa 查询时引发 ConcurrentModificationException

Jboss 7.2 root-logger level DEBUG provokes ConcurrentModificationException on executing a jpa query

java

logging

hibernate

concurrentmodification

jboss7.x