Uploaded image for project: 'Apache ServiceComb'
  1. Apache ServiceComb
  2. SCB-2201

Acceptance tests occasionally fails in CI

    XMLWordPrintableJSON

Details

    • Improvement
    • Status: Open
    • Major
    • Resolution: Unresolved
    • pack-0.6.0
    • None
    • Saga
    • None

    Description

       
       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] ------------------------------------------------------------------------

      Attachments

        Issue Links

          Activity

            People

              njiang Willem Jiang
              zhanglei Lei Zhang
              Votes:
              0 Vote for this issue
              Watchers:
              2 Start watching this issue

              Dates

                Created:
                Updated: