[
https://issues.apache.org/jira/browse/SCB-2201?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=17294080#comment-17294080
]
Willem Jiang commented on SCB-2201:
-----------------------------------
It's OK that the COORDINATED events are received in different order.
I think we can fix the issue by not checking the order of event.
> 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)
