Lei Zhang created SCB-2201:
------------------------------
Summary: 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
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)
