Setup (mostly Java):
- Spring boot application, running in a Kubernetes pod which exposes a webservice (through Swagger) to start a Gatling simulation.
- The simulation + some extra config is passed in the webservice call
- The Spring RestController passes this info to a backing service
- This service starts the Gatling process using Gatling.fromMap inside the running JVM
This all works fine, except for the logging. Our Spring app has logging of its own, but that stops being printed once Gatling has run once. Consider this log snippet:
. ____ _ __ _ _
/\ / ’ __ _ () __ __ _ \ \ \
( ( )__ | '_ | '| | ’ / ` | \ \ \
\/ )| |)| | | | | || (| | ) ) ) )
’ || .__|| ||| |_, | / / / /
=========||==============|/=////
:: Spring Boot :: (v2.7.3)13:30:32.449 [INFO ] c.k.x.e.Application - Starting Application using Java 17.0.7 on gatling-executor-774cf7d4b5-vrk7v with PID 216 (/application/BOOT-INF/classes started by 1002870000 in /application)
13:30:32.452 [INFO ] c.k.x.e.Application - The following 1 profile is active: “acc”
13:30:34.842 [INFO ] o.s.b.w.e.t.TomcatWebServer - Tomcat initialized with port(s): 8443 (https)
13:30:34.852 [INFO ] o.a.c.h.Http11NioProtocol - Initializing ProtocolHandler [“https-jsse-nio-8443”]
13:30:34.853 [INFO ] o.a.c.c.StandardService - Starting service [Tomcat]
13:30:34.853 [INFO ] o.a.c.c.StandardEngine - Starting Servlet engine: [Apache Tomcat/9.0.65]
13:30:34.955 [INFO ] o.a.c.c.C.[.[.[/X9Y-I/gatling-executor] - Initializing Spring embedded WebApplicationContext
13:30:34.955 [INFO ] o.s.b.w.s.c.ServletWebServerApplicationContext - Root WebApplicationContext: initialization completed in 2360 ms
13:30:36.412 [INFO ] o.a.c.h.Http11NioProtocol - Starting ProtocolHandler [“https-jsse-nio-8443”]
13:30:36.710 [INFO ] o.s.b.w.e.t.TomcatWebServer - Tomcat started on port(s): 8443 (https) with context path ‘/X9Y-I/gatling-executor’
13:30:36.811 [INFO ] o.s.b.w.e.t.TomcatWebServer - Tomcat initialized with port(s): 8080 (http)
13:30:36.812 [INFO ] o.a.c.h.Http11NioProtocol - Initializing ProtocolHandler [“http-nio-8080”]
13:30:36.812 [INFO ] o.a.c.c.StandardService - Starting service [Tomcat]
13:30:36.812 [INFO ] o.a.c.c.StandardEngine - Starting Servlet engine: [Apache Tomcat/9.0.65]
13:30:36.833 [INFO ] o.a.c.c.C.[.[.[/] - Initializing Spring embedded WebApplicationContext
13:30:36.833 [INFO ] o.s.b.w.s.c.ServletWebServerApplicationContext - Root WebApplicationContext: initialization completed in 116 ms
13:30:36.860 [INFO ] o.a.c.h.Http11NioProtocol - Starting ProtocolHandler [“http-nio-8080”]
13:30:36.862 [INFO ] o.s.b.w.e.t.TomcatWebServer - Tomcat started on port(s): 8080 (http) with context path ‘’
13:30:36.919 [INFO ] c.k.x.e.Application - Started Application in 5.298 seconds (JVM running for 5.88)
13:30:49.194 [INFO ] o.a.c.c.C.[.[.[/] - Initializing Spring DispatcherServlet ‘dispatcherServlet’
13:30:49.195 [INFO ] o.s.w.s.DispatcherServlet - Initializing Servlet ‘dispatcherServlet’
13:30:49.252 [INFO ] o.s.b.a.e.w.EndpointLinksResolver - Exposing 1 endpoint(s) beneath base path ‘/actuator’
13:30:51.692 [INFO ] o.s.w.s.DispatcherServlet - Completed initialization in 2497 ms
13:31:52.129 [INFO ] o.a.c.c.C.[.[.[/X9Y-I/gatling-executor] - Initializing Spring DispatcherServlet ‘dispatcherServlet’
13:31:52.129 [INFO ] o.s.w.s.DispatcherServlet - Initializing Servlet ‘dispatcherServlet’
13:31:53.344 [INFO ] o.s.w.s.DispatcherServlet - Completed initialization in 1215 ms
13:48:40.843 [INFO ] o.a.t.u.h.p.Cookie - A cookie header was received [notice_gdpr_prefs=0,1,2,3,4,5:;] that contained an invalid cookie. That cookie will be ignored.
Note: further occurrences of this error will be logged at DEBUG level.
13:48:40.846 [INFO ] c.k.x.u.f.KubernetesRequestLoggingFilter - GET /X9Y-I/gatling-executor/simulator/v2/start?simulation=com.xxx.performance.tests.gatling.forms.simulation.FormsSimulation&sync=false©ToBucket=true&concurrentUsers=600&extraParams=forms_requests_per_second%3D600]
13:48:40.861 [INFO ] c.k.x.e.s.i.GatlingServiceImpl - Starting Gatling process
13:48:40.958 [INFO ] i.g.c.c.GatlingConfiguration$ - Gatling will try to load ‘gatling.conf’ config file as ClassLoader resource.
13:48:41.333 [INFO ] a.e.s.Slf4jLogger - Slf4jLogger started
13:48:41.513 [WARN ] java.util.prefs - Couldn’t create user preferences directory. User preferences are unusable.
13:48:41.513 [WARN ] java.util.prefs - java.io.IOException: No such file or directory
13:48:43.236 [WARN ] java.util.prefs - Could not lock User prefs. Unix error code 2.
13:48:43.493 [INFO ] i.g.c.s.PopulationBuilder - Throttle is enabled, disabling pauses
Simulation com.xxx.performance.tests.gatling.forms.simulation.FormsSimulation started…
13:48:43.956 [INFO ] i.g.c.s.w.LogFileDataWriter - Initializing
13:48:43.956 [INFO ] i.g.c.s.w.ConsoleDataWriter - Initializing
13:48:43.963 [INFO ] i.g.c.s.w.LogFileDataWriter - Initialized
13:48:43.966 [INFO ] i.g.c.s.w.ConsoleDataWriter - Initialized================================================================================
2023-06-07 13:48:48 5s elapsed
---- Requests ------------------------------------------------------------------Global (OK=593 KO=0 )
Get form (OK=556 KO=0 )
Get prefill data for form (OK=37 KO=0 )---- Forms scenario ------------------------------------------------------------
active: 600 / done: 0… (omitted logs)
Simulation com.xxx.performance.tests.gatling.forms.simulation.FormsSimulation completed in 900 seconds
14:03:43.998 [INFO ] a.a.CoordinatedShutdown - Running CoordinatedShutdown with reason [ActorSystemTerminateReason]
Parsing log file(s)…
14:03:44.033 [INFO ] i.g.c.s.LogFileReader$ - Collected List(/data/gatling/formssimulation-20230607114843456/simulation.log) from formssimulation-20230607114843456
14:03:44.043 [INFO ] i.g.c.s.LogFileReader - First pass
14:03:44.126 [INFO ] i.g.c.s.LogFileReader - First pass, read 100000 lines
14:03:44.172 [INFO ] i.g.c.s.LogFileReader - First pass, read 200000 lines
14:03:44.222 [INFO ] i.g.c.s.LogFileReader - First pass, read 300000 lines
14:03:44.263 [INFO ] i.g.c.s.LogFileReader - First pass, read 400000 lines
14:03:44.306 [INFO ] i.g.c.s.LogFileReader - First pass, read 500000 lines
14:03:44.347 [INFO ] i.g.c.s.LogFileReader - First pass, read 600000 lines
14:03:44.390 [INFO ] i.g.c.s.LogFileReader - First pass, read 700000 lines
14:03:44.430 [INFO ] i.g.c.s.LogFileReader - First pass, read 800000 lines
14:03:44.464 [INFO ] i.g.c.s.LogFileReader - First pass done: read 873361 lines
14:03:44.474 [INFO ] i.g.c.s.LogFileReader - Second pass
14:03:45.625 [INFO ] i.g.c.s.LogFileReader - Second pass, read 100000 lines
14:03:46.351 [INFO ] i.g.c.s.LogFileReader - Second pass, read 200000 lines
14:03:46.972 [INFO ] i.g.c.s.LogFileReader - Second pass, read 300000 lines
14:03:47.567 [INFO ] i.g.c.s.LogFileReader - Second pass, read 400000 lines
14:03:48.160 [INFO ] i.g.c.s.LogFileReader - Second pass, read 500000 lines
14:03:48.748 [INFO ] i.g.c.s.LogFileReader - Second pass, read 600000 lines
14:03:49.319 [INFO ] i.g.c.s.LogFileReader - Second pass, read 700000 lines
14:03:49.894 [INFO ] i.g.c.s.LogFileReader - Second pass, read 800000 lines
14:03:50.315 [INFO ] i.g.c.s.LogFileReader - Second pass: read 873361 lines
Parsing log file(s) done
Generating reports…---- Global Information --------------------------------------------------------
request count 535740 (OK=285409 KO=250331)
min response time 3 (OK=15 KO=3 )
max response time 7448 (OK=4236 KO=7448 )
mean response time 83 (OK=50 KO=120 )
std deviation 284 (OK=89 KO=401 )
response time 50th percentile 27 (OK=34 KO=16 )
response time 75th percentile 45 (OK=55 KO=23 )
response time 95th percentile 175 (OK=115 KO=941 )
response time 99th percentile 1579 (OK=179 KO=1968 )
mean requests/sec 595.267 (OK=317.121 KO=278.146)
---- Response Time Distribution ------------------------------------------------
t < 800 ms 284768 ( 53%)
800 ms <= t < 1200 ms 449 ( 0%)
t >= 1200 ms 192 ( 0%)
failed 250331 ( 47%)
---- Errors --------------------------------------------------------------------
status.find.is(200), but actually found 503 233658 (93.34%)
status.find.is(200), but actually found 500 16673 ( 6.66%)
================================================================================Reports generated in 0s.
Please open the following file: file:///data/gatling/formssimulation-20230607114843456/index.htmlSimulation com.xxx.performance.tests.gatling.simulation.contentProxy.ContentProxySimulation started…
As you can see the last line is the start of the second call to the webservice, starting another process but none of the request logging appears (like at the beginning of the log snippet).
I’m not sure this is a bug so I decided to ask here first…
I’ve never had this before with an application.