search

apache / servicecomb-java-chassis

ServiceComb Java Chassis is a Software Development Kit (SDK) for rapid development of microservices in Java, providing service registration, service discovery, dynamic routing, and service management features
Apache License 2.0
1.91k stars 813 forks source link

Failed to flush rest response,服务使用spring session jdbc共享功能,契约接口偶现主键冲突 #2327

Closed songfeiyue closed 1 year ago

songfeiyue commented 3 years ago

经排查历史日志，非契约接口未出现过该异常 [pool-5-thread-7]2021-03-26 04:00:02.718 [ERROR] | Failed to flush rest response, operation:jobmonitor.job.getAppJobStatus, request uri:/rest/** | org.apache.servicecomb.common.rest.AbstractRestInvocation.onExecuteHttpServerFiltersFinish(AbstractRestInvocation.java:303) org.springframework.dao.DataIntegrityViolationException: PreparedStatementCallback; SQL [INSERT INTO sche.SPRING_SESSION##****SESSION#*#LAST_ACCESS_TIME, MAX_INACTIVE_INTERVAL, EXPIRY_TIME, PRINCIPAL_NAME) VALUES (?, ?, ?, ?, ?, ?, ?)]; ERROR: duplicate key value violates unique constraint "SPRING_SESSION#*# (PRIMARY_ID)=(a35447ba-36e6-4144-8ff4-c9ff1df5d70a) already exists.; nested exception is org.postgresql.util.PSQLException: ERROR: duplicate key value violates unique constraint "SPRING_SESSION#*#* (PRIMARY_ID)=(a35447ba-36e6-4144-8ff4-c9ff1df5d70a) already exists. at org.springframework.jdbc.support.SQLStateSQLExceptionTranslator.doTranslate(SQLStateSQLExceptionTranslator.java:104) ~[spring-jdbc-5.2.9.RELEASE.jar:5.2.9.RELEASE] at org.springframework.jdbc.support.AbstractFallbackSQLExceptionTranslator.translate(AbstractFallbackSQLExceptionTranslator.java:72) ~[spring-jdbc-5.2.9.RELEASE.jar:5.2.9.RELEASE] at org.springframework.jdbc.support.AbstractFallbackSQLExceptionTranslator.translate(AbstractFallbackSQLExceptionTranslator.java:81) ~[spring-jdbc-5.2.9.RELEASE.jar:5.2.9.RELEASE] at org.springframework.jdbc.support.AbstractFallbackSQLExceptionTranslator.translate(AbstractFallbackSQLExceptionTranslator.java:81) ~[spring-jdbc-5.2.9.RELEASE.jar:5.2.9.RELEASE] at org.springframework.jdbc.core.JdbcTemplate.translateException(JdbcTemplate.java:1443) ~[spring-jdbc-5.2.9.RELEASE.jar:5.2.9.RELEASE] at org.springframework.jdbc.core.JdbcTemplate.execute(JdbcTemplate.java:633) ~[spring-jdbc-5.2.9.RELEASE.jar:5.2.9.RELEASE] at org.springframework.jdbc.core.JdbcTemplate.update(JdbcTemplate.java:862) ~[spring-jdbc-5.2.9.RELEASE.jar:5.2.9.RELEASE] at org.springframework.jdbc.core.JdbcTemplate.update(JdbcTemplate.java:917) ~[spring-jdbc-5.2.9.RELEASE.jar:5.2.9.RELEASE] at org.springframework.session.jdbc.JdbcIndexedSessionRepository$JdbcSession.lambda$save$5(JdbcIndexedSessionRepository.java:783) ~[spring-session-jdbc-2.2.0.RELEASE.jar:2.2.0.RELEASE] at org.springframework.transaction.support.TransactionOperations.lambda$executeWithoutResult$0(TransactionOperations.java:68) ~[spring-tx-5.2.9.RELEASE.jar:5.2.9.RELEASE] at org.springframework.transaction.support.TransactionTemplate.execute(TransactionTemplate.java:140) ~[spring-tx-5.2.9.RELEASE.jar:5.2.9.RELEASE] at org.springframework.transaction.support.TransactionOperations.executeWithoutResult(TransactionOperations.java:67) ~[spring-tx-5.2.9.RELEASE.jar:5.2.9.RELEASE] at org.springframework.session.jdbc.JdbcIndexedSessionRepository$JdbcSession.save(JdbcIndexedSessionRepository.java:779) ~[spring-session-jdbc-2.2.0.RELEASE.jar:2.2.0.RELEASE] at org.springframework.session.jdbc.JdbcIndexedSessionRepository$JdbcSession.access$200(JdbcIndexedSessionRepository.java:631) ~[spring-session-jdbc-2.2.0.RELEASE.jar:2.2.0.RELEASE] at org.springframework.session.jdbc.JdbcIndexedSessionRepository.save(JdbcIndexedSessionRepository.java:409) ~[spring-session-jdbc-2.2.0.RELEASE.jar:2.2.0.RELEASE] at org.springframework.session.jdbc.JdbcIndexedSessionRepository.save(JdbcIndexedSessionRepository.java:130) ~[spring-session-jdbc-2.2.0.RELEASE.jar:2.2.0.RELEASE] at org.springframework.session.web.http.SessionRepositoryFilter$SessionRepositoryRequestWrapper.commitSession(SessionRepositoryFilter.java:225) ~[spring-session-core-2.2.0.RELEASE.jar:2.2.0.RELEASE] at org.springframework.session.web.http.SessionRepositoryFilter$SessionRepositoryRequestWrapper.access$100(SessionRepositoryFilter.java:192) ~[spring-session-core-2.2.0.RELEASE.jar:2.2.0.RELEASE] at org.springframework.session.web.http.SessionRepositoryFilter$SessionRepositoryResponseWrapper.onResponseCommitted(SessionRepositoryFilter.java:179) ~[spring-session-core-2.2.0.RELEASE.jar:2.2.0.RELEASE] at org.springframework.session.web.http.OnCommittedResponseWrapper.doOnResponseCommitted(OnCommittedResponseWrapper.java:227) ~[spring-session-core-2.2.0.RELEASE.jar:2.2.0.RELEASE] at org.springframework.session.web.http.OnCommittedResponseWrapper.flushBuffer(OnCommittedResponseWrapper.java:162) ~[spring-session-core-2.2.0.RELEASE.jar:2.2.0.RELEASE] at javax.servlet.ServletResponseWrapper.flushBuffer(ServletResponseWrapper.java:181) ~[tomcat-embed-core-9.0.43.jar:4.0.FR] at javax.servlet.ServletResponseWrapper.flushBuffer(ServletResponseWrapper.java:181) ~[tomcat-embed-core-9.0.43.jar:4.0.FR] at org.apache.servicecomb.foundation.vertx.http.StandardHttpServletResponseEx.flushBuffer(StandardHttpServletResponseEx.java:92) ~[foundation-vertx-8.00.111.jar:8.00.111] at org.apache.servicecomb.common.rest.AbstractRestInvocation.onExecuteHttpServerFiltersFinish(AbstractRestInvocation.java:301) ~[common-rest-8.00.111.jar:8.00.111] at org.apache.servicecomb.common.rest.AbstractRestInvocation.lambda$executeHttpServerFilters$3(AbstractRestInvocation.java:290) ~[common-rest-8.00.111.jar:8.00.111] at java.util.concurrent.CompletableFuture.uniWhenComplete(CompletableFuture.java:774) ~[?:1.8.0_272] at java.util.concurrent.CompletableFuture.uniWhenCompleteStage(CompletableFuture.java:792) ~[?:1.8.0_272] at java.util.concurrent.CompletableFuture.whenComplete(CompletableFuture.java:2153) ~[?:1.8.0_272] at org.apache.servicecomb.common.rest.AbstractRestInvocation.executeHttpServerFilters(AbstractRestInvocation.java:285) ~[common-rest-8.00.111.jar:8.00.111] at org.apache.servicecomb.common.rest.AbstractRestInvocation.sendResponse(AbstractRestInvocation.java:278) ~[common-rest-8.00.111.jar:8.00.111] at org.apache.servicecomb.common.rest.AbstractRestInvocation.sendResponseQuietly(AbstractRestInvocation.java:255) ~[common-rest-8.00.111.jar:8.00.111] at org.apache.servicecomb.common.rest.AbstractRestInvocation.lambda$doInvoke$2(AbstractRestInvocation.java:238) ~[common-rest-8.00.111.jar:8.00.111] at org.apache.servicecomb.swagger.invocation.AsyncResponse.complete(AsyncResponse.java:46) ~[swagger-invocation-core-8.00.111.jar:8.00.111] at rx.internal.util.ActionSubscriber.onNext(ActionSubscriber.java:39) ~[rxjava-1.1.6.jar:1.1.6] at rx.observers.SafeSubscriber.onNext(SafeSubscriber.java:139) ~[rxjava-1.1.6.jar:1.1.6] at rx.observers.Subscribers$5.onNext(Subscribers.java:235) ~[rxjava-1.1.6.jar:1.1.6] at rx.internal.operators.OperatorDoOnEach$1.onNext(OperatorDoOnEach.java:86) ~[rxjava-1.1.6.jar:1.1.6] at rx.observers.Subscribers$5.onNext(Subscribers.java:235) ~[rxjava-1.1.6.jar:1.1.6] at rx.internal.operators.OperatorDoOnEach$1.onNext(OperatorDoOnEach.java:86) ~[rxjava-1.1.6.jar:1.1.6] at rx.internal.operators.OperatorMap$MapSubscriber.onNext(OperatorMap.java:74) ~[rxjava-1.1.6.jar:1.1.6] at rx.observers.Subscribers$5.onNext(Subscribers.java:235) ~[rxjava-1.1.6.jar:1.1.6] at rx.observers.Subscribers$5.onNext(Subscribers.java:235) ~[rxjava-1.1.6.jar:1.1.6] at rx.internal.operators.OperatorDoOnEach$1.onNext(OperatorDoOnEach.java:86) ~[rxjava-1.1.6.jar:1.1.6] at rx.internal.operators.OperatorDoOnEach$1.onNext(OperatorDoOnEach.java:86) ~[rxjava-1.1.6.jar:1.1.6] at rx.internal.operators.OperatorDoOnEach$1.onNext(OperatorDoOnEach.java:86) ~[rxjava-1.1.6.jar:1.1.6] at rx.internal.operators.OperatorOnErrorResumeNextViaFunction$4.onNext(OperatorOnErrorResumeNextViaFunction.java:154) ~[rxjava-1.1.6.jar:1.1.6] at rx.internal.operators.OperatorDoOnEach$1.onNext(OperatorDoOnEach.java:86) ~[rxjava-1.1.6.jar:1.1.6] at rx.internal.operators.OperatorDoOnEach$1.onNext(OperatorDoOnEach.java:86) ~[rxjava-1.1.6.jar:1.1.6] at rx.observers.Subscribers$5.onNext(Subscribers.java:235) ~[rxjava-1.1.6.jar:1.1.6] at com.netflix.hystrix.AbstractCommand$DeprecatedOnRunHookApplication$1.onNext(AbstractCommand.java:1442) ~[hystrix-core-1.5.18.jar:1.5.18] at com.netflix.hystrix.AbstractCommand$ExecutionHookApplication$1.onNext(AbstractCommand.java:1368) ~[hystrix-core-1.5.18.jar:1.5.18] at org.apache.servicecomb.bizkeeper.BizkeeperCommand.lambda$null$1(BizkeeperCommand.java:87) ~[handler-bizkeeper-8.00.111.jar:8.00.111] at org.apache.servicecomb.swagger.engine.SwaggerProducerOperation.syncInvoke(SwaggerProducerOperation.java:167) ~[swagger-invocation-core-8.00.111.jar:8.00.111] at org.apache.servicecomb.swagger.engine.SwaggerProducerOperation.invoke(SwaggerProducerOperation.java:119) ~[swagger-invocation-core-8.00.111.jar:8.00.111] at org.apache.servicecomb.core.handler.impl.ProducerOperationHandler.handle(ProducerOperationHandler.java:40) ~[java-chassis-core-8.00.111.jar:8.00.111] at org.apache.servicecomb.core.Invocation.next(Invocation.java:204) ~[java-chassis-core-8.00.111.jar:8.00.111] at org.apache.servicecomb.bizkeeper.BizkeeperCommand.lambda$construct$2(BizkeeperCommand.java:79) ~[handler-bizkeeper-8.00.111.jar:8.00.111] at rx.internal.operators.OnSubscribeLift.call(OnSubscribeLift.java:50) ~[rxjava-1.1.6.jar:1.1.6] at rx.internal.operators.OnSubscribeLift.call(OnSubscribeLift.java:30) ~[rxjava-1.1.6.jar:1.1.6] at rx.internal.operators.OnSubscribeLift.call(OnSubscribeLift.java:50) ~[rxjava-1.1.6.jar:1.1.6] at rx.internal.operators.OnSubscribeLift.call(OnSubscribeLift.java:30) ~[rxjava-1.1.6.jar:1.1.6] at rx.Observable.unsafeSubscribe(Observable.java:8666) ~[rxjava-1.1.6.jar:1.1.6] at rx.internal.operators.OnSubscribeDefer.call(OnSubscribeDefer.java:52) ~[rxjava-1.1.6.jar:1.1.6] at rx.internal.operators.OnSubscribeDefer.call(OnSubscribeDefer.java:36) ~[rxjava-1.1.6.jar:1.1.6] at rx.internal.operators.OnSubscribeLift.call(OnSubscribeLift.java:50) ~[rxjava-1.1.6.jar:1.1.6] at rx.internal.operators.OnSubscribeLift.call(OnSubscribeLift.java:30) ~[rxjava-1.1.6.jar:1.1.6] at rx.internal.operators.OnSubscribeLift.call(OnSubscribeLift.java:50) ~[rxjava-1.1.6.jar:1.1.6] at rx.internal.operators.OnSubscribeLift.call(OnSubscribeLift.java:30) ~[rxjava-1.1.6.jar:1.1.6] at rx.internal.operators.OnSubscribeLift.call(OnSubscribeLift.java:50) ~[rxjava-1.1.6.jar:1.1.6] at rx.internal.operators.OnSubscribeLift.call(OnSubscribeLift.java:30) ~[rxjava-1.1.6.jar:1.1.6] at rx.internal.operators.OnSubscribeLift.call(OnSubscribeLift.java:50) ~[rxjava-1.1.6.jar:1.1.6] at rx.internal.operators.OnSubscribeLift.call(OnSubscribeLift.java:30) ~[rxjava-1.1.6.jar:1.1.6] at rx.internal.operators.OnSubscribeLift.call(OnSubscribeLift.java:50) ~[rxjava-1.1.6.jar:1.1.6] at rx.internal.operators.OnSubscribeLift.call(OnSubscribeLift.java:30) ~[rxjava-1.1.6.jar:1.1.6] at rx.internal.operators.OnSubscribeLift.call(OnSubscribeLift.java:50) ~[rxjava-1.1.6.jar:1.1.6] at rx.internal.operators.OnSubscribeLift.call(OnSubscribeLift.java:30) ~[rxjava-1.1.6.jar:1.1.6] at rx.internal.operators.OnSubscribeLift.call(OnSubscribeLift.java:50) ~[rxjava-1.1.6.jar:1.1.6] at rx.internal.operators.OnSubscribeLift.call(OnSubscribeLift.java:30) ~[rxjava-1.1.6.jar:1.1.6] at rx.Observable.unsafeSubscribe(Observable.java:8666) ~[rxjava-1.1.6.jar:1.1.6] at rx.internal.operators.OnSubscribeDefer.call(OnSubscribeDefer.java:52) ~[rxjava-1.1.6.jar:1.1.6] at rx.internal.operators.OnSubscribeDefer.call(OnSubscribeDefer.java:36) ~[rxjava-1.1.6.jar:1.1.6] at rx.internal.operators.OnSubscribeLift.call(OnSubscribeLift.java:50) ~[rxjava-1.1.6.jar:1.1.6] at rx.internal.operators.OnSubscribeLift.call(OnSubscribeLift.java:30) ~[rxjava-1.1.6.jar:1.1.6] at rx.internal.operators.OnSubscribeLift.call(OnSubscribeLift.java:50) ~[rxjava-1.1.6.jar:1.1.6] at rx.internal.operators.OnSubscribeLift.call(OnSubscribeLift.java:30) ~[rxjava-1.1.6.jar:1.1.6] at rx.internal.operators.OnSubscribeLift.call(OnSubscribeLift.java:50) ~[rxjava-1.1.6.jar:1.1.6] at rx.internal.operators.OnSubscribeLift.call(OnSubscribeLift.java:30) ~[rxjava-1.1.6.jar:1.1.6] at rx.internal.operators.OnSubscribeLift.call(OnSubscribeLift.java:50) ~[rxjava-1.1.6.jar:1.1.6] at rx.internal.operators.OnSubscribeLift.call(OnSubscribeLift.java:30) ~[rxjava-1.1.6.jar:1.1.6] at rx.Observable.unsafeSubscribe(Observable.java:8666) ~[rxjava-1.1.6.jar:1.1.6] at rx.internal.operators.OnSubscribeDefer.call(OnSubscribeDefer.java:52) ~[rxjava-1.1.6.jar:1.1.6] at rx.internal.operators.OnSubscribeDefer.call(OnSubscribeDefer.java:36) ~[rxjava-1.1.6.jar:1.1.6] at rx.Observable.subscribe(Observable.java:8759) ~[rxjava-1.1.6.jar:1.1.6] at rx.Observable.subscribe(Observable.java:8726) ~[rxjava-1.1.6.jar:1.1.6] at rx.Observable.subscribe(Observable.java:8619) ~[rxjava-1.1.6.jar:1.1.6] at org.apache.servicecomb.bizkeeper.BizkeeperHandler.handle(BizkeeperHandler.java:78) ~[handler-bizkeeper-8.00.111.jar:8.00.111] at org.apache.servicecomb.core.Invocation.next(Invocation.java:204) ~[java-chassis-core-8.00.111.jar:8.00.111] at org.apache.servicecomb.qps.ProviderQpsFlowControlHandler.handle(ProviderQpsFlowControlHandler.java:38) ~[handler-flowcontrol-qps-8.00.111.jar:8.00.111] at org.apache.servicecomb.core.Invocation.next(Invocation.java:204) ~[java-chassis-core-8.00.111.jar:8.00.111] at org.apache.servicecomb.common.rest.AbstractRestInvocation.doInvoke(AbstractRestInvocation.java:238) ~[common-rest-8.00.111.jar:8.00.111] at org.apache.servicecomb.common.rest.AbstractRestInvocation.invoke(AbstractRestInvocation.java:212) ~[common-rest-8.00.111.jar:8.00.111] at org.apache.servicecomb.common.rest.AbstractRestInvocation.runOnExecutor(AbstractRestInvocation.java:196) ~[common-rest-8.00.111.jar:8.00.111] at org.apache.servicecomb.common.rest.AbstractRestInvocation.lambda$scheduleInvocation$0(AbstractRestInvocation.java:159) ~[common-rest-8.00.111.jar:8.00.111] at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) [?:1.8.0_272] at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) [?:1.8.0_272] at java.lang.Thread.run(Thread.java:748) [?:1.8.0_272] Caused by: org.postgresql.util.PSQLException: ERROR: duplicate key value violates unique constraint "SPRING_SESSION*#*#***** (PRIMARY_ID)=(a35447ba-36e6-4144-8ff4-c9ff1df5d70a) already exists. at org.postgresql.core.v3.QueryExecutorImpl.receiveErrorResponse(QueryExecutorImpl.java:2196) ~[gaussdbv1.jdbc-V100R003C20SPC118.jar:?] at org.postgresql.core.v3.QueryExecutorImpl.processResults(QueryExecutorImpl.java:1925) ~[gaussdbv1.jdbc-V100R003C20SPC118.jar:?] at org.postgresql.core.v3.QueryExecutorImpl.execute(QueryExecutorImpl.java:345) ~[gaussdbv1.jdbc-V100R003C20SPC118.jar:?] at org.postgresql.jdbc2.AbstractJdbc2Statement.execute(AbstractJdbc2Statement.java:537) ~[gaussdbv1.jdbc-V100R003C20SPC118.jar:?] at org.postgresql.jdbc2.AbstractJdbc2Statement.executeWithFlags(AbstractJdbc2Statement.java:411) ~[gaussdbv1.jdbc-V100R003C20SPC118.jar:?] at org.postgresql.jdbc2.AbstractJdbc2Statement.executeUpdate(AbstractJdbc2Statement.java:357) ~[gaussdbv1.jdbc-V100R003C20SPC118.jar:?] at org.apache.commons.dbcp2.DelegatingPreparedStatement.executeUpdate(DelegatingPreparedStatement.java:136) ~[commons-dbcp2-2.7.0.jar:2.7.0] at org.apache.commons.dbcp2.DelegatingPreparedStatement.executeUpdate(DelegatingPreparedStatement.java:136) ~[commons-dbcp2-2.7.0.jar:2.7.0] at org.springframework.jdbc.core.JdbcTemplate.lambda$update$0(JdbcTemplate.java:867) ~[spring-jdbc-5.2.9.RELEASE.jar:5.2.9.RELEASE] at org.springframework.jdbc.core.JdbcTemplate.execute(JdbcTemplate.java:617) ~[spring-jdbc-5.2.9.RELEASE.jar:5.2.9.RELEASE] ... 101 more

songfeiyue commented 3 years ago

session jdbc的主键是uuid生成的，所以多实例之间出现主键冲突并无可能

songfeiyue commented 3 years ago

可能契约接口有重试机制导致的

liubao68 commented 3 years ago

日志堆栈比较难看出来是什么原因导致的。 个人的一些思路：

  1. 如果怀疑是重试，可以看看客户端调用的日志，一般重试会有错误日志，显示请求被重试了。 服务端的处理不会重试。 客户端重试配置
  2. 分析下业务逻辑，看看ID是否会因为客户端重试导致重复（比如ID是客户端传递过来的），如果不是ID不是客户端传递过来的， 而是服务端写数据库的时候自动生成的，那么就不一定是重试导致的。 如果是客户端传过来的， 那么是重试导致的可能性会很大。
liubao68 commented 1 year ago

close old issues, please feel free to submit a new one if the problem still exists.