Intermittent -broken simulation.log - java.lang.NumberFormatException: For input string: "161701795909url get request"

Gatling (Open-Source)
1

Hi,

I have noticed an intermittent issue when running tests which fails with connection times out.
I’m not sure if this is acoincidence but each time I see a broken report there are also error messages (connection timeout most of the cases)
I haven’t seen it so far for successfull tests.

The test I’m running is the following: 2000-5000 active users/injector with peak requests rate of 700req/sec.
Is there a way to avoid these exceptions ?

Thank you in advance!

gatling.version: 3.5.1 (tried also with 3.2.0 with same results)
gatling.maven.plugin.version:3.1.(3.0.5)

scala-maven-plugin.version 4.4.1(4.1.1)

Guilty line:

USER Varnish START 161701795909url get request 1617017959045 1617017959066 KO status.find.is(200), but actually found 429

Exception sample catched when trying to merge report from multiple injectors:

Exception in thread “main” java.lang.NumberFormatException: For input string: “161701795909url get request”
at java.lang.NumberFormatException.forInputString(NumberFormatException.java:65)
at java.lang.Long.parseLong(Long.java:589)
at java.lang.Long.parseLong(Long.java:631)
at scala.collection.StringOps$.toLong$extension(StringOps.scala:902)
at io.gatling.charts.stats.LogFileReader.$anonfun$firstPass$1(LogFileReader.scala:98)
at scala.collection.IterableOnceOps.foreach(IterableOnce.scala:553)
at scala.collection.IterableOnceOps.foreach$(IterableOnce.scala:551)
at scala.collection.AbstractIterator.foreach(Iterator.scala:1279)
at io.gatling.charts.stats.LogFileReader.firstPass(LogFileReader.scala:87)
at io.gatling.charts.stats.LogFileReader.$anonfun$firstPassData$1(LogFileReader.scala:139)
at io.gatling.charts.stats.LogFileReader.parseInputFiles(LogFileReader.scala:65)
at io.gatling.charts.stats.LogFileReader.(LogFileReader.scala:139)
at io.gatling.app.RunResultProcessor.initLogFileReader(RunResultProcessor.scala:52)
at io.gatling.app.RunResultProcessor.processRunResult(RunResultProcessor.scala:34)
at io.gatling.app.Gatling$.start(Gatling.scala:89)
at io.gatling.app.Gatling$.fromArgs(Gatling.scala:45)
at io.gatling.app.Gatling$.main(Gatling.scala:37)
at io.gatling.app.Gatling.main(Gatling.scala)

another example:

12:50:36,048 |-INFO in ch.qos.logback.classic.LoggerContext[default] - Could NOT find resource [logback-test.xml]
12:50:36,048 |-INFO in ch.qos.logback.classic.LoggerContext[default] - Could NOT find resource [logback.groovy]
12:50:36,048 |-INFO in ch.qos.logback.classic.LoggerContext[default] - Found resource [logback.xml] at [jar:file:zzzzz.jar!/logback.xml]
12:50:36,056 |-INFO in ch.qos.logback.core.joran.spi.ConfigurationWatchList@763d9750 - URL [jar:file:/opt/gatling/zzzzz.jar.jar!/logback.xml] is not of type file
12:50:36,099 |-INFO in ch.qos.logback.classic.joran.action.ConfigurationAction - debug attribute not set
12:50:36,099 |-INFO in ch.qos.logback.core.joran.action.AppenderAction - About to instantiate appender of type [ch.qos.logback.core.ConsoleAppender]
12:50:36,104 |-INFO in ch.qos.logback.core.joran.action.AppenderAction - Naming appender as [CONSOLE]
12:50:36,108 |-INFO in ch.qos.logback.core.joran.action.NestedComplexPropertyIA - Assuming default type [ch.qos.logback.classic.encoder.PatternLayoutEncoder] for [encoder] property
12:50:36,145 |-INFO in ch.qos.logback.core.joran.action.AppenderAction - About to instantiate appender of type [ch.qos.logback.core.FileAppender]
12:50:36,148 |-INFO in ch.qos.logback.core.joran.action.AppenderAction - Naming appender as [FILE]
12:50:36,153 |-INFO in ch.qos.logback.core.joran.action.NestedComplexPropertyIA - Assuming default type [ch.qos.logback.classic.encoder.PatternLayoutEncoder] for [encoder] property
12:50:36,153 |-INFO in ch.qos.logback.core.FileAppender[FILE] - File property is set to [GATLING_LOGS_IS_UNDEFINED/gatling_logs/test_loadtest-gatling-summary-936323-f2t95.log]
12:50:36,156 |-ERROR in ch.qos.logback.core.joran.spi.Interpreter@17:22 - no applicable action for [immediateFlush], current ElementPath is [[configuration][immediateFlush]]
12:50:36,156 |-INFO in ch.qos.logback.classic.joran.action.RootLoggerAction - Setting level of ROOT logger to ERROR
12:50:36,156 |-INFO in ch.qos.logback.core.joran.action.AppenderRefAction - Attaching appender named [CONSOLE] to Logger[ROOT]
12:50:36,156 |-INFO in ch.qos.logback.classic.joran.action.ConfigurationAction - End of configuration.
12:50:36,157 |-INFO in ch.qos.logback.classic.joran.JoranConfigurator@5c0369c4 - Registering current configuration as safe fallback point

Parsing log file(s)…
Exception in thread “main” java.lang.NumberFormatException: For input string: “START”
at java.lang.NumberFormatException.forInputString(NumberFormatException.java:65)
at java.lang.Long.parseLong(Long.java:589)
at java.lang.Long.parseLong(Long.java:631)
at scala.collection.StringOps$.toLong$extension(StringOps.scala:902)
at io.gatling.charts.stats.LogFileReader.$anonfun$firstPass$1(LogFileReader.scala:98)
at scala.collection.IterableOnceOps.foreach(IterableOnce.scala:553)
at scala.collection.IterableOnceOps.foreach$(IterableOnce.scala:551)
at scala.collection.AbstractIterator.foreach(Iterator.scala:1279)
at io.gatling.charts.stats.LogFileReader.firstPass(LogFileReader.scala:87)
at io.gatling.charts.stats.LogFileReader.$anonfun$firstPassData$1(LogFileReader.scala:139)
at io.gatling.charts.stats.LogFileReader.parseInputFiles(LogFileReader.scala:65)
at io.gatling.charts.stats.LogFileReader.(LogFileReader.scala:139)
at io.gatling.app.RunResultProcessor.initLogFileReader(RunResultProcessor.scala:52)
at io.gatling.app.RunResultProcessor.processRunResult(RunResultProcessor.scala:34)
at io.gatling.app.Gatling$.start(Gatling.scala:89)
at io.gatling.app.Gatling$.fromArgs(Gatling.scala:45)
at io.gatling.app.Gatling$.main(Gatling.scala:37)
at io.gatling.app.Gatling.main(Gatling.scala)

2

Honestly, no idea, all the more as this issue has never been reported until now.
Please provide a way to reproduce on our side.

3

You can use the below simplified sample script.
Run it from multiple injectors (keep increasing the injector number until it wil reproduce).
I noticed it crashed even with more gentle scenarios (3000-4000 req/sec).Workaround was to run test one more time but when huge amount of req/high error rate then the simulation.log is beyond repair and running it twice will produce the same result.

import scala.concurrent.duration._

class InfraSimulation extends Simulation {
val activeUser=200
val rampUpTime=10
val rpsAtPeakReachInSecs=80
val rpsAtPeak=700
val holdPeakRPSInSecs=60
val minPauseDuration=1
val maxPauseDuration=2
val rpsAtMean=40
val holdMeanRPSInSecs=60

private val users = constantUsersPerSec(activeUser) during (rampUpTime seconds)
private val varnishUrl: steps.GatlingSiteUrlGet = new steps.GatlingSiteUrlGet()

var scn = scenario(“Test”)
.repeat(5) {
exec(varnishUrl.VarnishGetCall(AppConfig.host)).pause(minPauseDuration, maxPauseDuration)
}

setUp(scn.inject(users))
.protocols(AppConfig.httpProtocol)
.throttle(reachRps(rpsAtPeak) in (rpsAtPeakReachInSecs seconds),
holdFor(holdPeakRPSInSecs seconds), jumpToRps(rpsAtMean), holdFor(holdMeanRPSInSecs seconds))

}

import io.gatling.core.Predef._
import io.gatling.http.Predef._

class GatlingSiteUrlGet {

def VarnishGetCall(hostname: String) = {
exec(http(“url get request”)
.get(“http://computer-database.gatling.io”)
.check(status.is(200))
)
}
}

4

Run it from multiple injectors (keep increasing the injector number until it will reproduce).

It looks like an issue with your custom made distributed Gatling solution.I recommend you have a look at FrontLine that officially supports this use case.

Regards,

5

So your suspicion is it is more something related to the environment than a software issue?

6

Most likely, yes.