Gatling never finish to pars log file(s)

[el...@jfrog.com]

Hi guys,

When I have a long scenario gatling never finish to write the results and exit with code 1,

the gatling-stdout.log ends with:

Simulation finished
Parsing log file(s)...

in gatling-stderr.log I see

Exception in thread "main" java.lang.reflect.InvocationTargetException
	at sun.reflect.NativeConstructorAccessorImpl.newInstance0(Native Method)
	at sun.reflect.NativeConstructorAccessorImpl.newInstance(NativeConstructorAccessorImpl.java:62)
	at sun.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:45)
	at java.lang.reflect.Constructor.newInstance(Constructor.java:423)
	at io.gatling.core.result.reader.DataReader$.newInstance(DataReader.scala:31)
	at io.gatling.app.Gatling.start(Gatling.scala:77)
	at io.gatling.app.Gatling$.fromArgs(Gatling.scala:59)
	at io.gatling.app.Gatling$.main(Gatling.scala:44)
	at io.gatling.app.Gatling.main(Gatling.scala)
Caused by: java.lang.IllegalArgumentException: Illegal Status value OConcurrent Download Scenario
	at io.gatling.core.result.message.Status$.apply(Status.scala:22)
	at io.gatling.charts.result.reader.RequestRecordParser.io$gatling$charts$result$reader$RequestRecordParser$$parseRequestRecord(Records.scala:59)
	at io.gatling.charts.result.reader.RequestRecordParser$$anonfun$unapply$2.apply(Records.scala:44)
	at io.gatling.charts.result.reader.RequestRecordParser$$anonfun$unapply$2.apply(Records.scala:44)
	at scala.Option.map(Option.scala:146)
	at io.gatling.charts.result.reader.RequestRecordParser.unapply(Records.scala:44)
	at io.gatling.charts.result.reader.FileDataReader$$anonfun$io$gatling$charts$result$reader$FileDataReader$$secondPass$1.apply(FileDataReader.scala:148)
	at io.gatling.charts.result.reader.FileDataReader$$anonfun$io$gatling$charts$result$reader$FileDataReader$$secondPass$1.apply(FileDataReader.scala:143)
	at scala.collection.Iterator$class.foreach(Iterator.scala:742)
	at scala.collection.AbstractIterator.foreach(Iterator.scala:1194)
	at io.gatling.charts.result.reader.FileDataReader.io$gatling$charts$result$reader$FileDataReader$$secondPass(FileDataReader.scala:143)
	at io.gatling.charts.result.reader.FileDataReader$$anonfun$7.apply(FileDataReader.scala:162)
	at io.gatling.charts.result.reader.FileDataReader$$anonfun$7.apply(FileDataReader.scala:162)
	at io.gatling.charts.result.reader.FileDataReader.doWithInputFiles(FileDataReader.scala:65)
	at io.gatling.charts.result.reader.FileDataReader.<init>(FileDataReader.scala:162)





in the bzt.log I can see
[2016-07-26 19:29:33,252 INFO Engine.gatling] Gatling tool exit code: 1
[2016-07-26 19:29:33,252 WARNING Engine] Please wait for graceful shutdown...
[2016-07-26 19:29:33,252 INFO Engine] Shutting down...
[2016-07-26 19:29:33,252 DEBUG Engine.local] Shutdown gatling/DownloadSimulation.scala
[2016-07-26 19:29:33,252 DEBUG Engine.gatling] Gatling worked for 54.1383559704 seconds
[2016-07-26 19:29:33,253 DEBUG Engine.monitoring.ServerAgentClient] Closing connection with stress1:4444
[2016-07-26 19:29:33,255 DEBUG Engine.Configuration] Dumping YAML config into /var/lib/jenkins/workspace/single-download-stress/artType/oss/dbType/derby/storageSize/50k/usersPerSec/400/results/2016-07-26_19-28-37.957950/effective.yml
[2016-07-26 19:29:33,294 DEBUG Engine.Configuration] Dumping JSON config into /var/lib/jenkins/workspace/single-download-stress/artType/oss/dbType/derby/storageSize/50k/usersPerSec/400/results/2016-07-26_19-28-37.957950/effective.json
[2016-07-26 19:29:33,297 DEBUG root] Caught exception in try: Traceback (most recent call last):
  File "/usr/local/lib/python2.7/dist-packages/bzt/cli.py", line 156, in perform
    self.engine.run()
  File "/usr/local/lib/python2.7/dist-packages/bzt/engine.py", line 139, in run
    self._wait()
  File "/usr/local/lib/python2.7/dist-packages/bzt/engine.py", line 166, in _wait
    while not self._check_modules_list():
  File "/usr/local/lib/python2.7/dist-packages/bzt/engine.py", line 156, in _check_modules_list
    finished |= module.check()
  File "/usr/local/lib/python2.7/dist-packages/bzt/modules/provisioning.py", line 88, in check
    finished &= executor.check()
  File "/usr/local/lib/python2.7/dist-packages/bzt/modules/gatling.py", line 350, in check
    raise RuntimeError("Gatling tool exited with non-zero code")
RuntimeError: Gatling tool exited with non-zero code

[2016-07-26 19:29:33,297 ERROR root] RuntimeError: Gatling tool exited with non-zero code
[2016-07-26 19:29:33,297 INFO Engine] Post-processing...
[2016-07-26 19:29:33,297 DEBUG Engine.local] Post-process gatling/DownloadSimulation.scala
[2016-07-26 19:29:33,297 DEBUG Engine] Add existing artifact (move=False): /var/lib/jenkins/workspace/single-download-stress/artType/oss/dbType/derby/storageSize/50k/usersPerSec/400/results/2016-07-26_19-28-37.957950/gatling-140326024855760-1469561323398/simulation.log
[2016-07-26 19:29:33,298 DEBUG Engine] Copying /var/lib/jenkins/workspace/single-download-stress/artType/oss/dbType/derby/storageSize/50k/usersPerSec/400/results/2016-07-26_19-28-37.957950/gatling-140326024855760-1469561323398/simulation.log to /var/lib/jenkins/workspace/single-download-stress/artType/oss/dbType/derby/storageSize/50k/usersPerSec/400/results/2016-07-26_19-28-37.957950/simulation.log
[2016-07-26 19:29:33,321 DEBUG Engine.gatling.DataLogReader] Reading gatling results
[2016-07-26 19:29:33,411 DEBUG Engine.gatling.DataLogReader] Buffer len: 8
[2016-07-26 19:29:33,411 DEBUG Engine.gatling.DataLogReader] Aggregating: 1469561357
[2016-07-26 19:29:34,161 DEBUG Engine.gatling.DataLogReader] Aggregating: 1469561358
[2016-07-26 19:29:34,785 DEBUG Engine.gatling.DataLogReader] Aggregating: 1469561359
[2016-07-26 19:29:35,357 DEBUG Engine.gatling.DataLogReader] Aggregating: 1469561360
[2016-07-26 19:29:35,983 DEBUG Engine.gatling.DataLogReader] Aggregating: 1469561361
[2016-07-26 19:29:36,621 DEBUG Engine.gatling.DataLogReader] Aggregating: 1469561362
[2016-07-26 19:29:37,531 DEBUG Engine.gatling.DataLogReader] Aggregating: 1469561363
[2016-07-26 19:29:38,154 DEBUG Engine.gatling.DataLogReader] Aggregating: 1469561364
[2016-07-26 19:29:38,631 DEBUG Engine.consolidator] Consolidator buffer[10]: [1469561355, 1469561356, 1469561357, 1469561358, 1469561359, 1469561360, 1469561361, 1469561362, 1469561363, 1469561364]
[2016-07-26 19:29:38,631 DEBUG Engine.consolidator] Merging into 1469561355
[2016-07-26 19:29:38,631 DEBUG Engine.consolidator] Merging 1469561355
[2016-07-26 19:29:39,559 DEBUG root] 1469561355 Alert: avg-rt>150ms for 0 sec: False
[2016-07-26 19:29:39,559 DEBUG root] 1469561355 Alert: rc_200>99% for 0 sec: False
[2016-07-26 19:29:39,560 DEBUG root] 1469561355 Alert: fail>1% for 0 sec: False
[2016-07-26 19:29:39,560 DEBUG root] 1469561355 Alert: succ<99% for 0 sec: False
[2016-07-26 19:29:39,582 DEBUG Engine.consolidator] Processed datapoint: 1469561355/None
[2016-07-26 19:29:39,583 DEBUG Engine.consolidator] Merging into 1469561356
[2016-07-26 19:29:39,583 DEBUG Engine.consolidator] Merging 1469561356
[2016-07-26 19:29:40,524 DEBUG root] 1469561356 Alert: avg-rt>150ms for 0 sec: False
[2016-07-26 19:29:40,525 DEBUG root] 1469561356 Alert: rc_200>99% for 0 sec: False
[2016-07-26 19:29:40,525 DEBUG root] 1469561356 Alert: fail>1% for 0 sec: False
[2016-07-26 19:29:40,525 DEBUG root] 1469561356 Alert: succ<99% for 0 sec: False
[2016-07-26 19:29:40,548 DEBUG Engine.consolidator] Processed datapoint: 1469561356/None
[2016-07-26 19:29:40,548 DEBUG Engine.consolidator] Merging into 1469561357
[2016-07-26 19:29:40,549 DEBUG Engine.consolidator] Merging 1469561357
[2016-07-26 19:29:41,769 DEBUG root] 1469561357 Alert: avg-rt>150ms for 0 sec: False
[2016-07-26 19:29:41,769 DEBUG root] 1469561357 Alert: rc_200>99% for 0 sec: False
[2016-07-26 19:29:41,769 DEBUG root] 1469561357 Alert: fail>1% for 0 sec: False
[2016-07-26 19:29:41,769 DEBUG root] 1469561357 Alert: succ<99% for 0 sec: False
[2016-07-26 19:29:41,793 DEBUG Engine.consolidator] Processed datapoint: 1469561357/None
[2016-07-26 19:29:41,793 DEBUG Engine.consolidator] Merging into 1469561358
[2016-07-26 19:29:41,794 DEBUG Engine.consolidator] Merging 1469561358
[2016-07-26 19:29:42,740 DEBUG root] 1469561358 Alert: avg-rt>150ms for 0 sec: False
[2016-07-26 19:29:42,741 DEBUG root] 1469561358 Alert: rc_200>99% for 0 sec: False
[2016-07-26 19:29:42,741 DEBUG root] 1469561358 Alert: fail>1% for 0 sec: False
[2016-07-26 19:29:42,741 DEBUG root] 1469561358 Alert: succ<99% for 0 sec: False
[2016-07-26 19:29:42,763 DEBUG Engine.consolidator] Processed datapoint: 1469561358/None
[2016-07-26 19:29:42,764 DEBUG Engine.consolidator] Merging into 1469561359
[2016-07-26 19:29:42,764 DEBUG Engine.consolidator] Merging 1469561359
[2016-07-26 19:29:43,662 DEBUG root] 1469561359 Alert: avg-rt>150ms for 0 sec: False
[2016-07-26 19:29:43,662 DEBUG root] 1469561359 Alert: rc_200>99% for 0 sec: False
[2016-07-26 19:29:43,663 DEBUG root] 1469561359 Alert: fail>1% for 0 sec: False
[2016-07-26 19:29:43,663 DEBUG root] 1469561359 Alert: succ<99% for 0 sec: False
[2016-07-26 19:29:43,687 DEBUG Engine.consolidator] Processed datapoint: 1469561359/None
[2016-07-26 19:29:43,688 DEBUG Engine.consolidator] Merging into 1469561360
[2016-07-26 19:29:43,688 DEBUG Engine.consolidator] Merging 1469561360
[2016-07-26 19:29:44,947 DEBUG root] 1469561360 Alert: avg-rt>150ms for 0 sec: False
[2016-07-26 19:29:44,948 DEBUG root] 1469561360 Alert: rc_200>99% for 0 sec: False
[2016-07-26 19:29:44,948 DEBUG root] 1469561360 Alert: fail>1% for 0 sec: False
[2016-07-26 19:29:44,948 DEBUG root] 1469561360 Alert: succ<99% for 0 sec: False
[2016-07-26 19:29:44,970 DEBUG Engine.consolidator] Processed datapoint: 1469561360/None
[2016-07-26 19:29:44,971 DEBUG Engine.consolidator] Merging into 1469561361
[2016-07-26 19:29:44,971 DEBUG Engine.consolidator] Merging 1469561361
[2016-07-26 19:29:45,935 DEBUG root] 1469561361 Alert: avg-rt>150ms for 0 sec: False
[2016-07-26 19:29:45,935 DEBUG root] 1469561361 Alert: rc_200>99% for 0 sec: False
[2016-07-26 19:29:45,935 DEBUG root] 1469561361 Alert: fail>1% for 0 sec: False
[2016-07-26 19:29:45,935 DEBUG root] 1469561361 Alert: succ<99% for 0 sec: False
[2016-07-26 19:29:45,959 DEBUG Engine.consolidator] Processed datapoint: 1469561361/None
[2016-07-26 19:29:45,961 DEBUG Engine.consolidator] Merging into 1469561362
[2016-07-26 19:29:45,961 DEBUG Engine.consolidator] Merging 1469561362
[2016-07-26 19:29:46,844 DEBUG root] 1469561362 Alert: avg-rt>150ms for 0 sec: False
[2016-07-26 19:29:46,844 DEBUG root] 1469561362 Alert: rc_200>99% for 0 sec: False
[2016-07-26 19:29:46,849 DEBUG root] 1469561362 Alert: fail>1% for 0 sec: False
[2016-07-26 19:29:46,849 DEBUG root] 1469561362 Alert: succ<99% for 0 sec: False
[2016-07-26 19:29:46,873 DEBUG Engine.consolidator] Processed datapoint: 1469561362/None
[2016-07-26 19:29:46,874 DEBUG Engine.consolidator] Merging into 1469561363
[2016-07-26 19:29:46,875 DEBUG Engine.consolidator] Merging 1469561363
[2016-07-26 19:29:47,836 DEBUG root] 1469561363 Alert: avg-rt>150ms for 0 sec: False
[2016-07-26 19:29:47,836 DEBUG root] 1469561363 Alert: rc_200>99% for 0 sec: False
[2016-07-26 19:29:47,836 DEBUG root] 1469561363 Alert: fail>1% for 0 sec: False
[2016-07-26 19:29:47,836 DEBUG root] 1469561363 Alert: succ<99% for 0 sec: False
[2016-07-26 19:29:47,858 DEBUG Engine.consolidator] Processed datapoint: 1469561363/None
[2016-07-26 19:29:47,859 DEBUG Engine.consolidator] Merging into 1469561364
[2016-07-26 19:29:47,860 DEBUG Engine.consolidator] Merging 1469561364
[2016-07-26 19:29:48,814 DEBUG root] 1469561364 Alert: avg-rt>150ms for 0 sec: False
[2016-07-26 19:29:48,815 DEBUG root] 1469561364 Alert: rc_200>99% for 0 sec: False
[2016-07-26 19:29:48,815 DEBUG root] 1469561364 Alert: fail>1% for 0 sec: False
[2016-07-26 19:29:48,815 DEBUG root] 1469561364 Alert: succ<99% for 0 sec: False
[2016-07-26 19:29:48,839 DEBUG Engine.consolidator] Processed datapoint: 1469561364/None
[2016-07-26 19:29:48,841 INFO Engine.final_stats] Test duration: 0:01:09
[2016-07-26 19:29:48,841 INFO Engine.final_stats] Samples count: 39964, 0.09% failures
[2016-07-26 19:29:48,841 INFO Engine.final_stats] Average times: total 0.024, latency 0.017, connect 0.000
[2016-07-26 19:29:48,841 INFO Engine.final_stats] Percentile 0.0%: 0.001
[2016-07-26 19:29:48,841 INFO Engine.final_stats] Percentile 50.0%: 0.014
[2016-07-26 19:29:48,842 INFO Engine.final_stats] Percentile 90.0%: 0.051
[2016-07-26 19:29:48,842 INFO Engine.final_stats] Percentile 95.0%: 0.072
[2016-07-26 19:29:48,842 INFO Engine.final_stats] Percentile 99.0%: 0.156
[2016-07-26 19:29:48,842 INFO Engine.final_stats] Percentile 99.9%: 0.528
[2016-07-26 19:29:48,842 INFO Engine.final_stats] Percentile 100.0%: 1.319
[2016-07-26 19:29:48,842 DEBUG Engine.console] No logger_handler or orig_stream was detected
[2016-07-26 19:29:48,843 DEBUG Engine.junit-xml] Processing passfail objects: [<bzt.modules.passfail.PassFailStatus object at 0x7fa032d62a50>]
[2016-07-26 19:29:48,843 INFO Engine.junit-xml] Writing JUnit XML report into: junit.xml
[2016-07-26 19:29:48,843 DEBUG root] 1469561364 Alert: avg-rt>300ms for 0 sec: False
[2016-07-26 19:29:48,843 DEBUG Engine.console] No logger_handler or orig_stream was detected
[2016-07-26 19:29:48,844 INFO Engine.final_stats] Test duration: 0:01:09
[2016-07-26 19:29:48,844 INFO Engine.final_stats] Samples count: 39964, 0.09% failures
[2016-07-26 19:29:48,844 INFO Engine.final_stats] Average times: total 0.024, latency 0.017, connect 0.000
[2016-07-26 19:29:48,844 INFO Engine.final_stats] Percentile 0.0%: 0.001
[2016-07-26 19:29:48,844 INFO Engine.final_stats] Percentile 50.0%: 0.014
[2016-07-26 19:29:48,844 INFO Engine.final_stats] Percentile 90.0%: 0.051
[2016-07-26 19:29:48,844 INFO Engine.final_stats] Percentile 95.0%: 0.072
[2016-07-26 19:29:48,845 INFO Engine.final_stats] Percentile 99.0%: 0.156
[2016-07-26 19:29:48,845 INFO Engine.final_stats] Percentile 99.9%: 0.528
[2016-07-26 19:29:48,845 INFO Engine.final_stats] Percentile 100.0%: 1.319
[2016-07-26 19:29:48,846 INFO Engine.final_stats] 2 failed samples: /org/apache/karaf/management/mbeans/org.apache.karaf.management.mbeans.bundles/2.2.5/org.apache.karaf.management.mbeans.bundles-2.2.5.pom
[2016-07-26 19:29:48,846 INFO Engine.final_stats] 4 failed samples: /org/apache/karaf/management/mbeans/org.apache.karaf.management.mbeans.bundles/2.2.9/org.apache.karaf.management.mbeans.bundles-2.2.9.pom
[2016-07-26 19:29:48,847 INFO Engine.final_stats] 9 failed samples: /org/apache/karaf/management/mbeans/org.apache.karaf.management.mbeans.packages/2.2.5/org.apache.karaf.management.mbeans.packages-2.2.5.pom
[2016-07-26 19:29:48,847 INFO Engine.final_stats] 8 failed samples: /org/apache/karaf/management/mbeans/org.apache.karaf.management.mbeans.packages/2.2.9/org.apache.karaf.management.mbeans.packages-2.2.9.pom
[2016-07-26 19:29:48,847 INFO Engine.final_stats] 8 failed samples: /org/apache/karaf/management/mbeans/org.apache.karaf.management.mbeans.services/2.2.8/org.apache.karaf.management.mbeans.services-2.2.8.pom
[2016-07-26 19:29:48,847 INFO Engine.final_stats] 5 failed samples: /org/apache/karaf/management/mbeans/org.apache.karaf.management.mbeans.services/2.2.9/org.apache.karaf.management.mbeans.services-2.2.9.pom
[2016-07-26 19:29:48,848 INFO Engine.final_stats] Dumping final status as CSV: dump.csv
[2016-07-26 19:29:49,256 DEBUG Engine.Configuration] Dumping YAML config into /var/lib/jenkins/workspace/single-download-stress/artType/oss/dbType/derby/storageSize/50k/usersPerSec/400/results/2016-07-26_19-28-37.957950/effective.yml
[2016-07-26 19:29:49,295 DEBUG Engine.Configuration] Dumping JSON config into /var/lib/jenkins/workspace/single-download-stress/artType/oss/dbType/derby/storageSize/50k/usersPerSec/400/results/2016-07-26_19-28-37.957950/effective.json
[2016-07-26 19:29:49,296 INFO root] Artifacts dir: /var/lib/jenkins/workspace/single-download-stress/artType/oss/dbType/derby/storageSize/50k/usersPerSec/400/results/2016-07-26_19-28-37.957950
[2016-07-26 19:29:49,297 WARNING root] Done performing with code: 1
[2016-07-26 19:29:49,297 DEBUG Engine] Add existing artifact (move=True): bzt.log
[2016-07-26 19:29:49,297 DEBUG Engine] Moving bzt.log to /var/lib/jenkins/workspace/single-download-stress/artType/oss/dbType/derby/storageSize/50k/usersPerSec/400/results/2016-07-26_19-28-37.957950/bzt.log




Any idea? is it related to taurus at all or compleatly gatling issue?

not sure if it is related but I have in my configuration
 consolidator:
    buffer-seconds: 5

Any help will be highly appreciated 

[Andrey Pokhilko]

Looks like purely gatling issue, it wrote results file that it were unable to analyze then :)

I'm not aware if there is a way to disable this analysis for Gatling, we would obtain an option to not do this by default.

Andrey Pohilko Chief Scientist P: +7 (909) 631-21-69

--
You received this message because you are subscribed to the Google Groups "codename-taurus" group.
To unsubscribe from this group and stop receiving emails from it, send an email to codename-taur...@googlegroups.com.
To view this discussion on the web visit https://groups.google.com/d/msgid/codename-taurus/2dc9cd12-21d0-4b09-b2c9-37ba54467fb8%40googlegroups.com.
For more options, visit https://groups.google.com/d/optout.