Hi.
Just a note to report a bizarre error impacting the identity matching.
I noticed bug #317. So I:
Toggled off "Update matched identities" Synchronization tasks / Edit /
Task screen for the MySQL resource.
Toggled on "reset token".
Ran the synchronization task.
This provoked a very different set of errors than I've been seeing for
this synchronization issue. I've pasted the log snippet in below. It's
consistent each time I try execute the synchronization with the "Update
matched identities" off. With this on, the log I'd reported earlier is
the consistent result.
As another weird side effect, the selected "User derived attributes" for
the "List users" view became unselected. This I haven't been able to
reproduce, though.
I suspect I've got some sort of database corruption. So I'll try wiping
out the postgres data store, starting over tomorrow evening.
Edward Siewick
Syncope v1.0.6 using Postgres 9.1.8
Tomcat7.0.26
java version "1.6.0_27"
OpenJDK Runtime Environment (IcedTea6 1.12.3) (6b27-1.12.3-0ubuntu1~12.04.1)
OpenJDK 64-Bit Server VM (build 20.0-b12, mixed mode)
ubuntu server 12.04
Connector to the MySQL resource is db.table 2.1.4.
22:19:16.971 DEBUG org.apache.syncope.core.scheduling.AbstractTaskJob -
Execute synchronization with token null
22:19:17.066 DEBUG org.apache.syncope.core.scheduling.AbstractTaskJob -
Process 'CREATE_OR_UPDATE' for '8'
22:19:17.114 DEBUG org.apache.syncope.core.scheduling.AbstractTaskJob -
SyncTask not configured for update
22:19:17.114 DEBUG org.apache.syncope.core.scheduling.AbstractTaskJob -
Process 'CREATE_OR_UPDATE' for '9'
22:19:17.145 DEBUG org.apache.syncope.core.scheduling.AbstractTaskJob -
SyncTask not configured for update
22:19:17.145 DEBUG org.apache.syncope.core.scheduling.AbstractTaskJob -
Process 'CREATE_OR_UPDATE' for '11'
22:19:17.178 DEBUG org.apache.syncope.core.scheduling.AbstractTaskJob -
SyncTask not configured for update
22:19:17.178 DEBUG org.apache.syncope.core.scheduling.AbstractTaskJob -
Process 'CREATE_OR_UPDATE' for '12'
22:19:17.209 DEBUG org.apache.syncope.core.scheduling.AbstractTaskJob -
SyncTask not configured for update
22:19:17.209 DEBUG org.apache.syncope.core.scheduling.AbstractTaskJob -
Process 'CREATE_OR_UPDATE' for '13'
22:19:17.240 DEBUG org.apache.syncope.core.scheduling.AbstractTaskJob -
SyncTask not configured for update
22:19:17.240 DEBUG org.apache.syncope.core.scheduling.AbstractTaskJob -
Process 'CREATE_OR_UPDATE' for '14'
22:19:18.542 ERROR org.apache.syncope.core.scheduling.AbstractTaskJob -
Could not create user 14
org.springframework.orm.jpa.JpaSystemException: The transaction has been
rolled back. See the nested exceptions for details on the errors that
occurred.; nested exception is <openjpa-2.2.1-r422266:1396819 fatal
general error> org.apache.openjpa.persistence.PersistenceException: The
transaction has been rolled back. See the nested exceptions for details
on the errors that occurred.
FailedObject:
org.apache.syncope.core.persistence.beans.user.SyncopeUser@47fd9166
at
org.springframework.orm.jpa.EntityManagerFactoryUtils.convertJpaAccessExceptionIfPossible(EntityManagerFactoryUtils.java:321)
~[spring-orm-3.1.4.RELEASE.jar:3.1.4.RELEASE]
at
org.springframework.orm.jpa.DefaultJpaDialect.translateExceptionIfPossible(DefaultJpaDialect.java:120)
~[spring-orm-3.1.4.RELEASE.jar:3.1.4.RELEASE]
at
org.springframework.orm.jpa.JpaTransactionManager.doCommit(JpaTransactionManager.java:516)
~[spring-orm-3.1.4.RELEASE.jar:3.1.4.RELEASE]
at
org.springframework.transaction.support.AbstractPlatformTransactionManager.processCommit(AbstractPlatformTransactionManager.java:754)
~[spring-tx-3.1.4.RELEASE.jar:3.1.4.RELEASE]
at
org.springframework.transaction.support.AbstractPlatformTransactionManager.commit(AbstractPlatformTransactionManager.java:723)
~[spring-tx-3.1.4.RELEASE.jar:3.1.4.RELEASE]
at
org.springframework.transaction.interceptor.TransactionAspectSupport.commitTransactionAfterReturning(TransactionAspectSupport.java:387)
~[spring-tx-3.1.4.RELEASE.jar:3.1.4.RELEASE]
at
org.springframework.transaction.interceptor.TransactionInterceptor.invoke(TransactionInterceptor.java:120)
~[spring-tx-3.1.4.RELEASE.jar:3.1.4.RELEASE]
at
org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:172)
~[spring-aop-3.1.4.RELEASE.jar:3.1.4.RELEASE]
at
org.springframework.aop.framework.JdkDynamicAopProxy.invoke(JdkDynamicAopProxy.java:202)
~[spring-aop-3.1.4.RELEASE.jar:3.1.4.RELEASE]
at sun.proxy.$Proxy86.create(Unknown Source) ~[na:na]
at
org.apache.syncope.core.scheduling.SyncJob.createUser(SyncJob.java:351)
[SyncJob.class:na]
at
org.apache.syncope.core.scheduling.SyncJob.handleDelta(SyncJob.java:777)
[SyncJob.class:na]
at
org.apache.syncope.core.scheduling.SyncJob$1.handle(SyncJob.java:706)
[SyncJob$1.class:na]
at
org.apache.syncope.core.propagation.ConnectorFacadeProxy$1.handle(ConnectorFacadeProxy.java:461)
[ConnectorFacadeProxy$1.class:na]
at
org.identityconnectors.framework.impl.api.StreamHandlerUtil$ObjectStreamHandlerAdapter.handle(StreamHandlerUtil.java:79)
[framework-internal-1.3.2.jar:na]
at
org.identityconnectors.framework.impl.api.BufferedResultsProxy.invoke(BufferedResultsProxy.java:268)
[framework-internal-1.3.2.jar:na]
at
org.identityconnectors.framework.impl.api.DelegatingTimeoutProxy.invoke(DelegatingTimeoutProxy.java:102)
[framework-internal-1.3.2.jar:na]
at sun.proxy.$Proxy116.search(Unknown Source) [na:na]
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
~[na:1.7.0_15]
at
sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57)
~[na:1.7.0_15]
at
sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
~[na:1.7.0_15]
at java.lang.reflect.Method.invoke(Method.java:601) ~[na:1.7.0_15]
at
org.identityconnectors.framework.impl.api.LoggingProxy.invoke(LoggingProxy.java:76)
[framework-internal-1.3.2.jar:na]
at sun.proxy.$Proxy116.search(Unknown Source) [na:na]
at
org.identityconnectors.framework.impl.api.AbstractConnectorFacade.search(AbstractConnectorFacade.java:142)
[framework-internal-1.3.2.jar:na]
at
org.apache.syncope.core.propagation.ConnectorFacadeProxy.getAllObjects(ConnectorFacadeProxy.java:451)
[ConnectorFacadeProxy.class:na]
at
org.apache.syncope.core.scheduling.SyncJob.doExecute(SyncJob.java:701)
[SyncJob.class:na]
at
org.apache.syncope.core.scheduling.AbstractTaskJob.execute(AbstractTaskJob.java:101)
[AbstractTaskJob.class:na]
at org.quartz.core.JobRunShell.run(JobRunShell.java:223)
[quartz-1.8.6.jar:na]
at
org.quartz.simpl.SimpleThreadPool$WorkerThread.run(SimpleThreadPool.java:549)
[quartz-1.8.6.jar:na]
Caused by: org.apache.openjpa.persistence.PersistenceException: The
transaction has been rolled back. See the nested exceptions for details
on the errors that occurred.
at
org.apache.openjpa.kernel.BrokerImpl.newFlushException(BrokerImpl.java:2339)
~[openjpa-2.2.1.jar:2.2.1]
at org.apache.openjpa.kernel.BrokerImpl.flush(BrokerImpl.java:2176)
~[openjpa-2.2.1.jar:2.2.1]
at
org.apache.openjpa.kernel.BrokerImpl.flushSafe(BrokerImpl.java:2074)
~[openjpa-2.2.1.jar:2.2.1]
at
org.apache.openjpa.kernel.BrokerImpl.beforeCompletion(BrokerImpl.java:1992)
~[openjpa-2.2.1.jar:2.2.1]
at
org.apache.openjpa.kernel.LocalManagedRuntime.commit(LocalManagedRuntime.java:81)
~[openjpa-2.2.1.jar:2.2.1]
at
org.apache.openjpa.kernel.BrokerImpl.commit(BrokerImpl.java:1516)
~[openjpa-2.2.1.jar:2.2.1]
at
org.apache.openjpa.kernel.DelegatingBroker.commit(DelegatingBroker.java:933)
~[openjpa-2.2.1.jar:2.2.1]
at
org.apache.openjpa.persistence.EntityManagerImpl.commit(EntityManagerImpl.java:570)
~[openjpa-2.2.1.jar:2.2.1]
at
org.springframework.orm.jpa.JpaTransactionManager.doCommit(JpaTransactionManager.java:512)
~[spring-orm-3.1.4.RELEASE.jar:3.1.4.RELEASE]
... 27 common frames omitted
Caused by: org.apache.openjpa.persistence.EntityExistsException: ERROR:
duplicate key value violates unique constraint "u_syncpsr_username"
Detail: Key (username)=(0014) already exists. {prepstmnt 1172332191
INSERT INTO public.syncopeuser (id, changepwddate, cipheralgorithm,
creationdate, failedlogins, lastlogindate, password, status, suspended,
token, tokenexpiretime, username, workflowid) VALUES (?, ?, ?, ?, ?, ?,
?, ?, ?, ?, ?, ?, ?)} [code=0, state=23505]
at
org.apache.openjpa.jdbc.sql.DBDictionary.narrow(DBDictionary.java:4943)
~[openjpa-2.2.1.jar:2.2.1]
at
org.apache.openjpa.jdbc.sql.DBDictionary.newStoreException(DBDictionary.java:4918)
~[openjpa-2.2.1.jar:2.2.1]
at
org.apache.openjpa.jdbc.sql.SQLExceptions.getStore(SQLExceptions.java:136)
~[openjpa-2.2.1.jar:2.2.1]
at
org.apache.openjpa.jdbc.sql.SQLExceptions.getStore(SQLExceptions.java:78) ~[openjpa-2.2.1.jar:2.2.1]
at
org.apache.openjpa.jdbc.kernel.PreparedStatementManagerImpl.flushAndUpdate(PreparedStatementManagerImpl.java:143)
~[openjpa-2.2.1.jar:2.2.1]
at
org.apache.openjpa.jdbc.kernel.BatchingPreparedStatementManagerImpl.flushAndUpdate(BatchingPreparedStatementManagerImpl.java:79)
~[openjpa-2.2.1.jar:2.2.1]
at
org.apache.openjpa.jdbc.kernel.PreparedStatementManagerImpl.flushInternal(PreparedStatementManagerImpl.java:99)
~[openjpa-2.2.1.jar:2.2.1]
at
org.apache.openjpa.jdbc.kernel.PreparedStatementManagerImpl.flush(PreparedStatementManagerImpl.java:87)
~[openjpa-2.2.1.jar:2.2.1]
at
org.apache.openjpa.jdbc.kernel.ConstraintUpdateManager.flush(ConstraintUpdateManager.java:357)
~[openjpa-2.2.1.jar:2.2.1]
at
org.apache.openjpa.jdbc.kernel.ConstraintUpdateManager.flushGraph(ConstraintUpdateManager.java:349)
~[openjpa-2.2.1.jar:2.2.1]
at
org.apache.openjpa.jdbc.kernel.ConstraintUpdateManager.flush(ConstraintUpdateManager.java:97)
~[openjpa-2.2.1.jar:2.2.1]
at
org.apache.openjpa.jdbc.kernel.BatchingConstraintUpdateManager.flush(BatchingConstraintUpdateManager.java:59)
~[openjpa-2.2.1.jar:2.2.1]
at
org.apache.openjpa.jdbc.kernel.AbstractUpdateManager.flush(AbstractUpdateManager.java:105)
~[openjpa-2.2.1.jar:2.2.1]
at
org.apache.openjpa.jdbc.kernel.AbstractUpdateManager.flush(AbstractUpdateManager.java:78)
~[openjpa-2.2.1.jar:2.2.1]
at
org.apache.openjpa.jdbc.kernel.JDBCStoreManager.flush(JDBCStoreManager.java:735)
~[openjpa-2.2.1.jar:2.2.1]
at
org.apache.openjpa.kernel.DelegatingStoreManager.flush(DelegatingStoreManager.java:131)
~[openjpa-2.2.1.jar:2.2.1]
at
org.apache.openjpa.datacache.DataCacheStoreManager.flush(DataCacheStoreManager.java:661)
~[openjpa-2.2.1.jar:2.2.1]
at
org.apache.openjpa.kernel.DelegatingStoreManager.flush(DelegatingStoreManager.java:131)
~[openjpa-2.2.1.jar:2.2.1]
... 35 common frames omitted
Caused by: org.apache.openjpa.lib.jdbc.ReportingSQLException: ERROR:
duplicate key value violates unique constraint "u_syncpsr_username"
Detail: Key (username)=(0014) already exists. {prepstmnt 1172332191
INSERT INTO public.syncopeuser (id, changepwddate, cipheralgorithm,
creationdate, failedlogins, lastlogindate, password, status, suspended,
token, tokenexpiretime, username, workflowid) VALUES (?, ?, ?, ?, ?, ?,
?, ?, ?, ?, ?, ?, ?)} [code=0, state=23505]
at
org.apache.openjpa.lib.jdbc.LoggingConnectionDecorator.wrap(LoggingConnectionDecorator.java:219)
~[openjpa-2.2.1.jar:2.2.1]
at
org.apache.openjpa.lib.jdbc.LoggingConnectionDecorator.wrap(LoggingConnectionDecorator.java:195)
~[openjpa-2.2.1.jar:2.2.1]
at
org.apache.openjpa.lib.jdbc.LoggingConnectionDecorator.access$1000(LoggingConnectionDecorator.java:59)
~[openjpa-2.2.1.jar:2.2.1]
at
org.apache.openjpa.lib.jdbc.LoggingConnectionDecorator$LoggingConnection$LoggingPreparedStatement.executeUpdate(LoggingConnectionDecorator.java:1134)
~[openjpa-2.2.1.jar:2.2.1]
at
org.apache.openjpa.lib.jdbc.DelegatingPreparedStatement.executeUpdate(DelegatingPreparedStatement.java:272)
~[openjpa-2.2.1.jar:2.2.1]
at
org.apache.openjpa.lib.jdbc.DelegatingPreparedStatement.executeUpdate(DelegatingPreparedStatement.java:272)
~[openjpa-2.2.1.jar:2.2.1]
at
org.apache.openjpa.jdbc.kernel.JDBCStoreManager$CancelPreparedStatement.executeUpdate(JDBCStoreManager.java:1765)
~[openjpa-2.2.1.jar:2.2.1]
at
org.apache.openjpa.jdbc.kernel.PreparedStatementManagerImpl.executeUpdate(PreparedStatementManagerImpl.java:267)
~[openjpa-2.2.1.jar:2.2.1]
at
org.apache.openjpa.jdbc.kernel.PreparedStatementManagerImpl.flushAndUpdate(PreparedStatementManagerImpl.java:118)
~[openjpa-2.2.1.jar:2.2.1]
... 48 common frames omitted
22:19:18.544 DEBUG org.apache.syncope.core.scheduling.AbstractTaskJob -
Sync result: Users [created/failures]: 0/1 [updated/failures]: 0/0
[deleted/ failures]: 0/0
Failed to create: CREATE FAILURE (id/ name): null/ null with message:
The transaction has been rolled back. See the nested exceptions for
details on the errors that occurred.; nested exception is
<openjpa-2.2.1-r422266:1396819 fatal general error>
org.apache.openjpa.persistence.PersistenceException: The transaction has
been rolled back. See the nested exceptions for details on the errors
that occurred.
FailedObject:
org.apache.syncope.core.persistence.beans.user.SyncopeUser@47fd9166
Created:
Updated:
Deleted:
