[ https://issues.apache.org/jira/browse/SCB-2201?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel ]
Willem Jiang reassigned SCB-2201: --------------------------------- Assignee: Willem Jiang > Acceptance tests occasionally fails in CI > ------------------------------------------ > > Key: SCB-2201 > URL: https://issues.apache.org/jira/browse/SCB-2201 > Project: Apache ServiceComb > Issue Type: Improvement > Components: Saga > Affects Versions: pack-0.6.0 > Reporter: Lei Zhang > Assignee: Willem Jiang > Priority: Major > > > 021-03-02T15:13:13.3306582Z When User UserA requests to order 2 units of > ProductA with unit price 2 success # PackStepdefs.java:65 > 2021-03-02T15:13:13.4457584Z alpha> 2021-03-02 15:13:13.443 INFO > ba04d452e180 --- [nio-8090-exec-5] o.a.s.p.a.s.t.AlphaTccEventController : > Get the events request > 2021-03-02T15:13:13.4502117Z alpha> 2021-03-02 15:13:13.447 INFO > ba04d452e180 --- [nio-8090-exec-5] o.a.s.p.a.s.t.AlphaTccEventController : > Get the event size 8 > 2021-03-02T15:13:13.4570031Z 15:13:13.456 [main] INFO > org.apache.servicecomb.pack.StepDefSupport - Retrieved data > [{serviceName=ordering, txType=STARTED}, {serviceName=inventory, > txType=P_TX_STATED}, {serviceName=inventory, txType=P_TX_ENDED}, > {serviceName=payment, txType=P_TX_STATED}, {serviceName=payment, > txType=P_TX_ENDED}, {serviceName=ordering, txType=ENDED}, > {serviceName=payment, txType=COORDINATED}, {serviceName=inventory, > txType=COORDINATED}] from service > 2021-03-02T15:13:13.4629108Z Then Alpha records the following events > # PackStepdefs.java:85 > 2021-03-02T15:13:13.4638659Z cucumber.runtime.table.TableDiffException: > Tables were not identical: > 2021-03-02T15:13:13.4639806Z | serviceName | txType | > 2021-03-02T15:13:13.4640429Z | ordering | STARTED | > 2021-03-02T15:13:13.4641082Z | inventory | P_TX_STATED | > 2021-03-02T15:13:13.4641719Z | inventory | P_TX_ENDED | > 2021-03-02T15:13:13.4642129Z | payment | P_TX_STATED | > 2021-03-02T15:13:13.4642570Z | payment | P_TX_ENDED | > 2021-03-02T15:13:13.4642939Z | ordering | ENDED | > 2021-03-02T15:13:13.4643645Z - | inventory | COORDINATED | > 2021-03-02T15:13:13.4644098Z | payment | COORDINATED | > 2021-03-02T15:13:13.4644518Z + | inventory | COORDINATED | > 2021-03-02T15:13:13.4644796Z > 2021-03-02T15:13:13.4645714Z at > cucumber.runtime.table.TableDiffer.calculateDiffs(TableDiffer.java:41) > 2021-03-02T15:13:13.4646889Z at > cucumber.api.DataTable.diff(DataTable.java:180) > 2021-03-02T15:13:13.4648203Z at > org.apache.servicecomb.pack.StepDefSupport.dataMatches(StepDefSupport.java:77) > 2021-03-02T15:13:13.4651920Z at > org.apache.servicecomb.pack.StepDefSupport.dataMatches(StepDefSupport.java:53) > 2021-03-02T15:13:13.4653617Z at > org.apache.servicecomb.pack.PackStepdefs.lambda$new$6(PackStepdefs.java:91) > 2021-03-02T15:13:13.4656175Z at ✽.Alpha records the following > events(src/test/resources/pack_tcc_confirm_scenario.feature:26) > 2021-03-02T15:13:13.4656756Z > 2021-03-02T15:13:13.4657360Z And Inventory Service contains the following > booking orders # PackStepdefs.java:94 > 2021-03-02T15:13:13.4658908Z And Payment Service contains the following > booking orders # PackStepdefs.java:98 > 2021-03-02T15:13:13.4660493Z 15:13:13.465 [main] INFO > org.apache.servicecomb.pack.PackStepdefs - Cleaning up services > 2021-03-02T15:13:13.5379644Z > 2021-03-02T15:13:13.5383278Z Failed scenarios: > 2021-03-02T15:13:13.5387094Z > src/test/resources/pack_tcc_confirm_scenario.feature:18 # Everything is normal > 2021-03-02T15:13:13.5389875Z > 2021-03-02T15:13:13.5409913Z 2 Scenarios (1 failed, 1 passed) > 2021-03-02T15:13:13.5435380Z 16 Steps (1 failed, 2 skipped, 13 passed) > 2021-03-02T15:13:13.5436127Z 0m9.546s > 2021-03-02T15:13:13.5436567Z > 2021-03-02T15:13:13.5437553Z cucumber.runtime.table.TableDiffException: > Tables were not identical: > 2021-03-02T15:13:13.5438924Z | serviceName | txType | > 2021-03-02T15:13:13.5440100Z | ordering | STARTED | > 2021-03-02T15:13:13.5480498Z | inventory | P_TX_STATED | > 2021-03-02T15:13:13.5481247Z | inventory | P_TX_ENDED | > 2021-03-02T15:13:13.5482043Z | payment | P_TX_STATED | > 2021-03-02T15:13:13.5482556Z | payment | P_TX_ENDED | > 2021-03-02T15:13:13.5483057Z | ordering | ENDED | > 2021-03-02T15:13:13.5484133Z - | inventory | COORDINATED | > 2021-03-02T15:13:13.5484978Z | payment | COORDINATED | > 2021-03-02T15:13:13.5485524Z + | inventory | COORDINATED | > 2021-03-02T15:13:13.5485917Z > 2021-03-02T15:13:13.5486936Z at > cucumber.runtime.table.TableDiffer.calculateDiffs(TableDiffer.java:41) > 2021-03-02T15:13:13.5488245Z at > cucumber.api.DataTable.diff(DataTable.java:180) > 2021-03-02T15:13:13.5489670Z at > org.apache.servicecomb.pack.StepDefSupport.dataMatches(StepDefSupport.java:77) > 2021-03-02T15:13:13.5491631Z at > org.apache.servicecomb.pack.StepDefSupport.dataMatches(StepDefSupport.java:53) > 2021-03-02T15:13:13.5493434Z at > org.apache.servicecomb.pack.PackStepdefs.lambda$new$6(PackStepdefs.java:91) > 2021-03-02T15:13:13.5495470Z at ✽.Alpha records the following > events(src/test/resources/pack_tcc_confirm_scenario.feature:26) > 2021-03-02T15:13:13.5496237Z > 2021-03-02T15:13:13.5591618Z Tests run: 2, Failures: 0, Errors: 1, Skipped: > 0, Time elapsed: 9.862 sec <<< FAILURE! - in > org.apache.servicecomb.pack.RunCucumberIT > 2021-03-02T15:13:13.5593284Z Everything is normal(Alpha records transaction > events) Time elapsed: 2.426 sec <<< ERROR! > 2021-03-02T15:13:13.5594477Z cucumber.runtime.table.TableDiffException: > 2021-03-02T15:13:13.5595462Z Tables were not identical: > 2021-03-02T15:13:13.5596121Z | serviceName | txType | > 2021-03-02T15:13:13.5596892Z | ordering | STARTED | > 2021-03-02T15:13:13.5597543Z | inventory | P_TX_STATED | > 2021-03-02T15:13:13.5598210Z | inventory | P_TX_ENDED | > 2021-03-02T15:13:13.5598853Z | payment | P_TX_STATED | > 2021-03-02T15:13:13.5599543Z | payment | P_TX_ENDED | > 2021-03-02T15:13:13.5600167Z | ordering | ENDED | > 2021-03-02T15:13:13.5601174Z - | inventory | COORDINATED | > 2021-03-02T15:13:13.5604206Z | payment | COORDINATED | > 2021-03-02T15:13:13.5604655Z + | inventory | COORDINATED | > 2021-03-02T15:13:13.5604919Z > 2021-03-02T15:13:13.5605102Z > 2021-03-02T15:13:13.8966188Z > 2021-03-02T15:13:13.8966868Z Results : > 2021-03-02T15:13:13.8967113Z > 2021-03-02T15:13:13.8967414Z Tests in error: > 2021-03-02T15:13:13.8967792Z Tables were not identical: > 2021-03-02T15:13:13.8968216Z | serviceName | txType | > 2021-03-02T15:13:13.8968636Z | ordering | STARTED | > 2021-03-02T15:13:13.8969030Z | inventory | P_TX_STATED | > 2021-03-02T15:13:13.8969434Z | inventory | P_TX_ENDED | > 2021-03-02T15:13:13.8969819Z | payment | P_TX_STATED | > 2021-03-02T15:13:13.8970205Z | payment | P_TX_ENDED | > 2021-03-02T15:13:13.8971035Z | ordering | ENDED | > 2021-03-02T15:13:13.8971991Z - | inventory | COORDINATED | > 2021-03-02T15:13:13.8972449Z | payment | COORDINATED | > 2021-03-02T15:13:13.8972870Z + | inventory | COORDINATED | > 2021-03-02T15:13:13.8973146Z > 2021-03-02T15:13:13.8973328Z > 2021-03-02T15:13:13.8973693Z Tests run: 2, Failures: 0, Errors: 1, Skipped: 0 > 2021-03-02T15:13:13.8973997Z > 2021-03-02T15:13:13.8974250Z [INFO] > 2021-03-02T15:13:13.8975196Z [INFO] --- docker-maven-plugin:0.28.0:stop > (stop) @ acceptance-pack-tcc-spring-demo --- > 2021-03-02T15:13:13.9445689Z alpha> 2021-03-02 15:13:13.943 INFO > ba04d452e180 --- [ault-executor-1] o.a.s.p.a.s.t.GrpcTccEventService : > Disconnect from alpha, service [ordering] instanceId [ordering-172.17.0.6]. > 2021-03-02T15:13:14.4746686Z [INFO] DOCKER> [tcc-ordering:0.7.0-SNAPSHOT] > "ordering": Stop and removed container 436b4ebfa4ea after 0 ms > 2021-03-02T15:13:15.1026082Z [INFO] DOCKER> [tcc-payment:0.7.0-SNAPSHOT] > "payment": Stop and removed container bfd239e0968d after 0 ms > 2021-03-02T15:13:15.1699241Z inventory> 2021-03-02 15:13:15.169 INFO 1 --- [ > Thread-6] com.zaxxer.hikari.HikariDataSource : HikariPool-1 - > Shutdown initiated... > 2021-03-02T15:13:15.1716497Z inventory> 2021-03-02 15:13:15.170 INFO 1 --- > [pool-4-thread-1] .a.s.p.o.c.g.c.PushBackReconnectRunnable : Retry connecting > to alpha at alpha-server.servicecomb.io:8080 > 2021-03-02T15:13:15.6719915Z [INFO] DOCKER> [tcc-inventory:0.7.0-SNAPSHOT] > "inventory": Stop and removed container 1674858e08fe after 0 ms > 2021-03-02T15:13:15.7466669Z alpha> 2021-03-02 15:13:15.745 INFO > ba04d452e180 --- [ Thread-10] j.LocalContainerEntityManagerFactoryBean : > Closing JPA EntityManagerFactory for persistence unit 'default' > 2021-03-02T15:13:15.7577297Z alpha> 2021-03-02 15:13:15.757 INFO > ba04d452e180 --- [ Thread-10] c.z.h.HikariDataSource : > HikariPool-1 - Shutdown initiated... > 2021-03-02T15:13:15.7745201Z alpha> 2021-03-02 15:13:15.772 INFO > ba04d452e180 --- [ Thread-10] c.z.h.HikariDataSource : > HikariPool-1 - Shutdown completed. > 2021-03-02T15:13:16.2892987Z [INFO] DOCKER> [alpha-server:0.7.0-SNAPSHOT] > "alpha": Stop and removed container ba04d452e180 after 0 ms > 2021-03-02T15:13:16.3040637Z postgres> 2021-03-02 15:13:16.303 UTC [1] LOG: > received fast shutdown request > 2021-03-02T15:13:16.3080802Z postgres> 2021-03-02 15:13:16.304 UTC [1] LOG: > aborting any active transactions > 2021-03-02T15:13:16.3082271Z postgres> 2021-03-02 15:13:16.306 UTC [1] LOG: > background worker "logical replication launcher" (PID 81) exited with exit > code 1 > 2021-03-02T15:13:16.3083337Z postgres> 2021-03-02 15:13:16.307 UTC [76] LOG: > shutting down > 2021-03-02T15:13:16.3189814Z postgres> 2021-03-02 15:13:16.318 UTC [1] LOG: > database system is shut down > 2021-03-02T15:13:16.4972460Z [INFO] DOCKER> [postgres:latest] "postgres": > Stop and removed container 8b1a17525e57 after 0 ms > 2021-03-02T15:13:16.4973252Z [INFO] > 2021-03-02T15:13:16.4974675Z [INFO] --- maven-failsafe-plugin:2.19.1:verify > (default) @ acceptance-pack-tcc-spring-demo --- > 2021-03-02T15:13:16.4975906Z [INFO] > ------------------------------------------------------------------------ > 2021-03-02T15:13:16.4985378Z [INFO] Reactor Summary: > 2021-03-02T15:13:16.4985774Z [INFO] > 2021-03-02T15:13:16.4986249Z [INFO] Pack:Acceptance Tests > .............................. SUCCESS [ 3.356 s] > 2021-03-02T15:13:16.4986994Z [INFO] Pack:Acceptance Tests:Common > ....................... SUCCESS [ 0.817 s] > 2021-03-02T15:13:16.4987659Z [INFO] Pack:Acceptance Tests::Dubbo > ....................... SUCCESS [01:27 min] > 2021-03-02T15:13:16.4988281Z [INFO] Pack:Acceptance Tests::Spring > ...................... SUCCESS [01:23 min] > 2021-03-02T15:13:16.4988926Z [INFO] Pack:Acceptance Tests::TCC::Spring > ................. FAILURE [01:09 min] > 2021-03-02T15:13:16.4989578Z [INFO] Pack:Acceptance Tests::Cluster Spring > .............. SKIPPED > 2021-03-02T15:13:16.4990249Z [INFO] Pack:Acceptance Tests::Spring with consul > .......... SKIPPED > 2021-03-02T15:13:16.4990926Z [INFO] Pack:Acceptance Tests::Spring with > zookeeper ....... SKIPPED > 2021-03-02T15:13:16.4991606Z [INFO] Pack:Acceptance Tests::Spring with nacos > ........... SKIPPED > 2021-03-02T15:13:16.4992255Z [INFO] Pack:Acceptance Tests::Akka Spring > ................. SKIPPED > 2021-03-02T15:13:16.4993223Z [INFO] > ------------------------------------------------------------------------ > 2021-03-02T15:13:16.4993751Z [INFO] BUILD FAILURE > 2021-03-02T15:13:16.4994474Z [INFO] > ------------------------------------------------------------------------ -- This message was sent by Atlassian Jira (v8.3.4#803005)