View Issue Details

IDProjectCategoryView StatusLast Update
0004124SymmetricDSBugpublic2019-11-04 07:27
ReportermkurzAssigned To 
Prioritynormal 
Status newResolutionopen 
Product Version3.9.20 
Target VersionFixed in Version 
Summary0004124: sym_registration_request -> duplicate key
DescriptionWe observe 1-70 cases of the following exception every day for sql server db's with up to 350 nodes:

org.jumpmind.db.sql.UniqueKeyException: com.microsoft.sqlserver.jdbc.SQLServerException: Violation of PRIMARY KEY constraint 'PK__sym_regi__89EADC886767D057'. Cannot insert duplicate key in object 'dbo.sym_registration_request'. The duplicate key value is (mobil, clientxy, 2019-10-28 12:55:01.5670000).: Error while processing GET request for node: 222 at 127.0.0.1 with path: /central-0/pull

That's strange, because the create_time of sym_registration_request is part of the PK. It stands out that it seems to be always(?) with the ip 127.0.0.1.
We observe this on different central machines.

Steps To ReproduceThe only way we could reproduce this was doing 2 inserts into 1 transaction:
BEGIN TRANSACTION

INSERT INTO sym_registration_request
            (node_group_id,
             external_id,
             status,
             create_time,
             last_update_time,
             host_name,
             ip_address)
VALUES ( 'mobil',
             'x',
             'OK',
             CURRENT_TIMESTAMP,
             CURRENT_TIMESTAMP,
             'h',
             '127.0')

INSERT INTO sym_registration_request
            (node_group_id,
             external_id,
             status,
             create_time,
             last_update_time,
             host_name,
             ip_address)
VALUES ( 'mobil',
             'x',
             'OK',
             CURRENT_TIMESTAMP,
             CURRENT_TIMESTAMP,
             'h',
             '127.0')

COMMIT

But that isn't the case in the symmetricds code.
Additional Informationfull stack trace:
org.jumpmind.db.sql.UniqueKeyException: com.microsoft.sqlserver.jdbc.SQLServerException: Violation of PRIMARY KEY constraint 'PK__sym_regi__89EADC886767D057'. Cannot insert duplicate key in object 'dbo.sym_registration_request'. The duplicate key value is (mobil, clientxy, 2019-10-28 12:55:01.5670000).: Error while processing GET request for node: 222 at 127.0.0.1 with path: /central-0/pull
org.jumpmind.db.sql.AbstractSqlTemplate.translate(AbstractSqlTemplate.java:296)
org.jumpmind.db.sql.AbstractSqlTemplate.translate(AbstractSqlTemplate.java:291)
org.jumpmind.db.sql.JdbcSqlTemplate.execute(JdbcSqlTemplate.java:503)
org.jumpmind.db.sql.JdbcSqlTemplate.update(JdbcSqlTemplate.java:342)
org.jumpmind.symmetric.service.impl.RegistrationService.saveRegistrationRequest(RegistrationService.java:371)
org.jumpmind.symmetric.service.impl.RegistrationService.processRegistration(RegistrationService.java:272)
org.jumpmind.symmetric.service.impl.RegistrationService.registerNode(RegistrationService.java:295)
org.jumpmind.symmetric.web.PullUriHandler.handlePull(PullUriHandler.java:120)
org.jumpmind.symmetric.web.PullUriHandler.handleWithCompression(PullUriHandler.java:100)
org.jumpmind.symmetric.web.AbstractCompressionUriHandler.handle(AbstractCompressionUriHandler.java:84)
org.jumpmind.symmetric.web.SymmetricServlet.service(SymmetricServlet.java:114)
javax.servlet.http.HttpServlet.service(HttpServlet.java:790)
org.eclipse.jetty.servlet.ServletHolder.handle(ServletHolder.java:864)
org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1655)
org.jumpmind.symmetric.web.LogRequestResponseFilter.doFilter(LogRequestResponseFilter.java:53)
org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1634)
org.eclipse.jetty.websocket.server.WebSocketUpgradeFilter.doFilter(WebSocketUpgradeFilter.java:215)
org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1642)
org.jumpmind.symmetric.web.HttpMethodFilter.doFilter(HttpMethodFilter.java:62)
org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1642)
org.eclipse.jetty.servlet.ServletHandler.doHandle(ServletHandler.java:533)
org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:146)
org.eclipse.jetty.security.SecurityHandler.handle(SecurityHandler.java:548)
org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:132)
org.eclipse.jetty.server.handler.ScopedHandler.nextHandle(ScopedHandler.java:257)
org.eclipse.jetty.server.session.SessionHandler.doHandle(SessionHandler.java:1595)
org.eclipse.jetty.server.handler.ScopedHandler.nextHandle(ScopedHandler.java:255)
org.eclipse.jetty.server.handler.ContextHandler.doHandle(ContextHandler.java:1253)
org.eclipse.jetty.server.handler.ScopedHandler.nextScope(ScopedHandler.java:203)
org.eclipse.jetty.servlet.ServletHandler.doScope(ServletHandler.java:473)
org.eclipse.jetty.server.session.SessionHandler.doScope(SessionHandler.java:1564)
org.eclipse.jetty.server.handler.ScopedHandler.nextScope(ScopedHandler.java:201)
org.eclipse.jetty.server.handler.ContextHandler.doScope(ContextHandler.java:1155)
org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:144)
org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:132)
org.eclipse.jetty.server.Server.handle(Server.java:531)
org.eclipse.jetty.server.HttpChannel.handle(HttpChannel.java:352)
org.eclipse.jetty.server.HttpConnection.onFillable(HttpConnection.java:260)
org.eclipse.jetty.io.AbstractConnection$ReadCallback.succeeded(AbstractConnection.java:281)
org.eclipse.jetty.io.FillInterest.fillable(FillInterest.java:102)
org.eclipse.jetty.io.ChannelEndPoint$2.run(ChannelEndPoint.java:118)
org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.doProduce(EatWhatYouKill.java:319)
org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.tryProduce(EatWhatYouKill.java:175)
org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.run(EatWhatYouKill.java:133)
org.eclipse.jetty.util.thread.ReservedThreadExecutor$ReservedThread.run(ReservedThreadExecutor.java:366)
org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:754)
org.eclipse.jetty.util.thread.QueuedThreadPool$2.run(QueuedThreadPool.java:672)
java.lang.Thread.run(Thread.java:748)
TagsNo tags attached.

Activities

mkurz

2019-11-04 07:27

reporter   ~0001627

I could reproduce this by doing:
update sym_node_security set registration_enabled=1 where node_id=1

Then PullUriHandler.java -> registrationService.registerNode(... is executed by the next requests, which causes the Exceptions in this case.

This could be fixed by a synchronized named mutex in RegistrationService . See. Pull request
https://github.com/JumpMind/symmetric-ds/pull/107

I our case this is caused by nodes which were set as offline nodes by a custom implementation of IOfflineServerListener, when the nodes come online again.

Issue History

Date Modified Username Field Change
2019-10-28 09:41 mkurz New Issue
2019-11-04 07:27 mkurz Note Added: 0001627