Uploaded image for project: 'Trusted authentication framework'
  1. Trusted authentication framework
  2. TRUSTAUTH-12

User creation on on first login fails because the XWikiAllGroup update is not thread safe

    XMLWordPrintable

Details

    • Bug
    • Resolution: Unresolved
    • Major
    • None
    • 1.3
    • API
    • None
    • Unknown

    Description

      Upon login of a user for the first time I got the following exception:

      2021-10-12 10:58:56,421 [...] WARN  o.h.e.j.s.SqlExceptionHelper   - SQL Error: 1062, SQLState: 23000 
      2021-10-12 10:58:56,421 [...] ERROR o.h.e.j.s.SqlExceptionHelper   - Duplicate entry '-4873478859632756605' for key 'PRIMARY' 
      2021-10-12 10:58:56,441 [...] ERROR o.x.c.a.i.DefaultUserManager   - Failed to create user [xwiki:XWiki.<redacted>] 
      com.xpn.xwiki.XWikiException: Error number 8002 in 8: Cannot create user XWiki.<redacted>
      	at com.xpn.xwiki.XWiki.createUser(XWiki.java:4184)
      	at com.xpn.xwiki.XWiki.createUser(XWiki.java:4091)
      	at com.xpn.xwiki.XWiki.createUser(XWiki.java:4066)
      	at org.xwiki.contrib.authentication.internal.DefaultUserManager.createUser(DefaultUserManager.java:83)
      	at org.xwiki.contrib.authentication.internal.DefaultTrustedAuthenticator.synchronizeUser(DefaultTrustedAuthenticator.java:279)
      	at org.xwiki.contrib.authentication.internal.DefaultTrustedAuthenticator.authenticate(DefaultTrustedAuthenticator.java:193)
      	at org.xwiki.contrib.authentication.internal.DefaultTrustedAuthenticator.authenticate(DefaultTrustedAuthenticator.java:166)
      	at org.xwiki.contrib.authentication.internal.DefaultTrustedAuthenticator.authenticate(DefaultTrustedAuthenticator.java:134)
      	at org.xwiki.contrib.authentication.internal.DefaultTrustedAuthenticator.authenticate(DefaultTrustedAuthenticator.java:108)
      	at org.xwiki.contrib.authentication.XWikiTrustedAuthenticator.checkAuth(XWikiTrustedAuthenticator.java:63)
      	at com.xpn.xwiki.XWiki.checkAuth(XWiki.java:4295)
      	at org.xwiki.security.authorization.internal.XWikiCachingRightService.authenticateUser(XWikiCachingRightService.java:241)
      	at org.xwiki.security.authorization.internal.XWikiCachingRightService.checkAccess(XWikiCachingRightService.java:271)
      	at com.xpn.xwiki.XWiki.checkAccess(XWiki.java:4313)
      	at com.xpn.xwiki.XWiki.prepareDocuments(XWiki.java:5503)
      	at com.xpn.xwiki.web.XWikiAction.execute(XWikiAction.java:404)
      	at com.xpn.xwiki.web.XWikiAction.execute(XWikiAction.java:218)
      	at org.apache.struts.action.RequestProcessor.processActionPerform(RequestProcessor.java:425)
      	at org.apache.struts.action.RequestProcessor.process(RequestProcessor.java:228)
      	at org.apache.struts.action.ActionServlet.process(ActionServlet.java:1913)
      	at org.apache.struts.action.ActionServlet.doGet(ActionServlet.java:449)
      	at javax.servlet.http.HttpServlet.service(HttpServlet.java:635)
      	at javax.servlet.http.HttpServlet.service(HttpServlet.java:742)
      	at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:231)
      	at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166)
      	at com.xpn.xwiki.web.ActionFilter.doFilter(ActionFilter.java:112)
      	at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193)
      	at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166)
      	at org.xwiki.wysiwyg.filter.ConversionFilter.doFilter(ConversionFilter.java:109)
      	at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193)
      	at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166)
      	at org.xwiki.container.servlet.filters.internal.SetHTTPHeaderFilter.doFilter(SetHTTPHeaderFilter.java:63)
      	at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193)
      	at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166)
      	at org.xwiki.container.servlet.filters.internal.SavedRequestRestorerFilter.doFilter(SavedRequestRestorerFilter.java:208)
      	at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193)
      	at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166)
      	at org.xwiki.container.servlet.filters.internal.SetCharacterEncodingFilter.doFilter(SetCharacterEncodingFilter.java:111)
      	at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193)
      	at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166)
      	at org.xwiki.resource.servlet.RoutingFilter.doFilter(RoutingFilter.java:132)
      	at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193)
      	at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166)
      	at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:200)
      	at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:96)
      	at org.apache.catalina.authenticator.AuthenticatorBase.invoke(AuthenticatorBase.java:493)
      	at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:140)
      	at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:81)
      	at org.apache.catalina.valves.AbstractAccessLogValve.invoke(AbstractAccessLogValve.java:650)
      	at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:87)
      	at org.apache.catalina.valves.RemoteIpValve.invoke(RemoteIpValve.java:679)
      	at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:342)
      	at org.apache.coyote.http11.Http11Processor.service(Http11Processor.java:800)
      	at org.apache.coyote.AbstractProcessorLight.process(AbstractProcessorLight.java:66)
      	at org.apache.coyote.AbstractProtocol$ConnectionHandler.process(AbstractProtocol.java:806)
      	at org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.doRun(NioEndpoint.java:1498)
      	at org.apache.tomcat.util.net.SocketProcessorBase.run(SocketProcessorBase.java:49)
      	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
      	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
      	at org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61)
      	at java.lang.Thread.run(Thread.java:748)
      Caused by: com.xpn.xwiki.XWikiException: Error number 3201 in 3: Exception while saving document xwiki:XWiki.XWikiAllGroup
      	at com.xpn.xwiki.store.XWikiHibernateStore.saveXWikiDoc(XWikiHibernateStore.java:668)
      	at com.xpn.xwiki.store.XWikiCacheStore.saveXWikiDoc(XWikiCacheStore.java:227)
      	at com.xpn.xwiki.store.XWikiCacheStore.saveXWikiDoc(XWikiCacheStore.java:217)
      	at com.xpn.xwiki.XWiki.saveDocument(XWiki.java:2020)
      	at com.xpn.xwiki.XWiki.saveDocument(XWiki.java:1944)
      	at com.xpn.xwiki.XWiki.addUserToGroup(XWiki.java:4225)
      	at com.xpn.xwiki.XWiki.setUserDefaultGroup(XWiki.java:4209)
      	at com.xpn.xwiki.XWiki.createUser(XWiki.java:4179)
      	... 60 common frames omitted
      Caused by: javax.persistence.PersistenceException: org.hibernate.exception.ConstraintViolationException: could not execute statement
      	at org.hibernate.internal.ExceptionConverterImpl.convert(ExceptionConverterImpl.java:154)
      	at org.hibernate.internal.ExceptionConverterImpl.convert(ExceptionConverterImpl.java:181)
      	at org.hibernate.internal.ExceptionConverterImpl.convert(ExceptionConverterImpl.java:188)
      	at org.hibernate.internal.SessionImpl.doFlush(SessionImpl.java:1348)
      	at org.hibernate.internal.SessionImpl.managedFlush(SessionImpl.java:435)
      	at org.hibernate.internal.SessionImpl.flushBeforeTransactionCompletion(SessionImpl.java:3221)
      	at org.hibernate.internal.SessionImpl.beforeTransactionCompletion(SessionImpl.java:2389)
      	at org.hibernate.engine.jdbc.internal.JdbcCoordinatorImpl.beforeTransactionCompletion(JdbcCoordinatorImpl.java:447)
      	at org.hibernate.resource.transaction.backend.jdbc.internal.JdbcResourceLocalTransactionCoordinatorImpl.beforeCompletionCallback(JdbcResourceLocalTransactionCoordinatorImpl.java:183)
      	at org.hibernate.resource.transaction.backend.jdbc.internal.JdbcResourceLocalTransactionCoordinatorImpl.access$300(JdbcResourceLocalTransactionCoordinatorImpl.java:40)
      	at org.hibernate.resource.transaction.backend.jdbc.internal.JdbcResourceLocalTransactionCoordinatorImpl$TransactionDriverControlImpl.commit(JdbcResourceLocalTransactionCoordinatorImpl.java:281)
      	at org.hibernate.engine.transaction.internal.TransactionImpl.commit(TransactionImpl.java:101)
      	at com.xpn.xwiki.internal.store.hibernate.HibernateStore.endTransaction(HibernateStore.java:832)
      	at com.xpn.xwiki.store.XWikiHibernateBaseStore.endTransaction(XWikiHibernateBaseStore.java:603)
      	at com.xpn.xwiki.store.XWikiHibernateStore.saveXWikiDoc(XWikiHibernateStore.java:659)
      	... 67 common frames omitted
      Caused by: org.hibernate.exception.ConstraintViolationException: could not execute statement
      	at org.hibernate.exception.internal.SQLExceptionTypeDelegate.convert(SQLExceptionTypeDelegate.java:59)
      	at org.hibernate.exception.internal.StandardSQLExceptionConverter.convert(StandardSQLExceptionConverter.java:42)
      	at org.hibernate.engine.jdbc.spi.SqlExceptionHelper.convert(SqlExceptionHelper.java:113)
      	at org.hibernate.engine.jdbc.spi.SqlExceptionHelper.convert(SqlExceptionHelper.java:99)
      	at org.hibernate.engine.jdbc.internal.ResultSetReturnImpl.executeUpdate(ResultSetReturnImpl.java:200)
      	at org.hibernate.persister.entity.AbstractEntityPersister.insert(AbstractEntityPersister.java:3208)
      	at org.hibernate.persister.entity.AbstractEntityPersister.insert(AbstractEntityPersister.java:3722)
      	at org.hibernate.action.internal.EntityInsertAction.execute(EntityInsertAction.java:91)
      	at org.hibernate.engine.spi.ActionQueue.executeActions(ActionQueue.java:604)
      	at org.hibernate.engine.spi.ActionQueue.lambda$executeActions$1(ActionQueue.java:478)
      	at java.util.LinkedHashMap.forEach(LinkedHashMap.java:684)
      	at org.hibernate.engine.spi.ActionQueue.executeActions(ActionQueue.java:475)
      	at org.hibernate.event.internal.AbstractFlushingEventListener.performExecutions(AbstractFlushingEventListener.java:348)
      	at org.hibernate.event.internal.DefaultFlushEventListener.onFlush(DefaultFlushEventListener.java:40)
      	at org.hibernate.event.service.internal.EventListenerGroupImpl.fireEventOnEachListener(EventListenerGroupImpl.java:108)
      	at org.hibernate.internal.SessionImpl.doFlush(SessionImpl.java:1344)
      	... 78 common frames omitted
      Caused by: com.mysql.jdbc.exceptions.jdbc4.MySQLIntegrityConstraintViolationException: Duplicate entry '-4873478859632756605' for key 'PRIMARY'
      	at sun.reflect.NativeConstructorAccessorImpl.newInstance0(Native Method)
      	at sun.reflect.NativeConstructorAccessorImpl.newInstance(NativeConstructorAccessorImpl.java:62)
      	at sun.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:45)
      	at java.lang.reflect.Constructor.newInstance(Constructor.java:423)
      	at com.mysql.jdbc.Util.handleNewInstance(Util.java:425)
      	at com.mysql.jdbc.Util.getInstance(Util.java:408)
      	at com.mysql.jdbc.SQLError.createSQLException(SQLError.java:936)
      	at com.mysql.jdbc.MysqlIO.checkErrorPacket(MysqlIO.java:3933)
      	at com.mysql.jdbc.MysqlIO.checkErrorPacket(MysqlIO.java:3869)
      	at com.mysql.jdbc.MysqlIO.sendCommand(MysqlIO.java:2524)
      	at com.mysql.jdbc.MysqlIO.sqlQueryDirect(MysqlIO.java:2675)
      	at com.mysql.jdbc.ConnectionImpl.execSQL(ConnectionImpl.java:2465)
      	at com.mysql.jdbc.PreparedStatement.executeInternal(PreparedStatement.java:1912)
      	at com.mysql.jdbc.PreparedStatement.executeUpdateInternal(PreparedStatement.java:2133)
      	at com.mysql.jdbc.PreparedStatement.executeUpdateInternal(PreparedStatement.java:2067)
      	at com.mysql.jdbc.PreparedStatement.executeLargeUpdate(PreparedStatement.java:5175)
      	at com.mysql.jdbc.PreparedStatement.executeUpdate(PreparedStatement.java:2052)
      	at org.apache.commons.dbcp2.DelegatingPreparedStatement.executeUpdate(DelegatingPreparedStatement.java:136)
      	at org.apache.commons.dbcp2.DelegatingPreparedStatement.executeUpdate(DelegatingPreparedStatement.java:136)
      	at org.apache.commons.dbcp2.DelegatingPreparedStatement.executeUpdate(DelegatingPreparedStatement.java:136)
      	at org.hibernate.engine.jdbc.internal.ResultSetReturnImpl.executeUpdate(ResultSetReturnImpl.java:197)
      	... 89 common frames omitted
      2021-10-12 10:58:56,449 [...] ERROR .i.DefaultTrustedAuthenticator - Unable to synchronize user profile for user [xwiki:XWiki.<redacted>], ended with public access. 
      

      I checked the database data and the ID of -4873478859632756605 belongs to an object of type XWikGroups in the page XWikiAllGroup. The history of XWikiAllGroup shows that that object was saved at 1 second distance from the moment when the concurrent exception ocurrs.

      Attachments

        Activity

          People

            Unassigned Unassigned
            lucaa Anca Luca
            Votes:
            0 Vote for this issue
            Watchers:
            1 Start watching this issue

            Dates

              Created:
              Updated: