# Gatling appears to be hijacking stdout logging **URL:** \ **Category:** Gatling (Open-Source)\ **Created:** [June 8, 2023, 2:22pm UTC](https://community.gatling.io/t/gatling-appears-to-be-hijacking-stdout-logging/8012 "2023-06-08T14:22:47Z")\ **Posts on this page:** 3\ **Page:** 1
**Author:** ![senn](https://avatars.discourse-cdn.com/v4/letter/s/d26b3c/32.png) [@senn](https://community.gatling.io/u/senn)\ **Post date:** [June 8, 2023, 2:22pm UTC](https://community.gatling.io/t/gatling-appears-to-be-hijacking-stdout-logging/8012/1 "2023-06-08T14:22:47Z")
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.html > > Simulation 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. ---
**Author:** ![slandelle](https://dub1.discourse-cdn.com/flex013/user_avatar/community.gatling.io/slandelle/32/4_2.png) [@slandelle](https://community.gatling.io/u/slandelle)\ **Post date:** [June 8, 2023, 4:32pm UTC](https://community.gatling.io/t/gatling-appears-to-be-hijacking-stdout-logging/8012/2 "2023-06-08T16:32:08Z")
Gatling is a software, not a library, and is not meant to be embedded in a in-house application. ---
**Author:** ![system](https://europe1.discourse-cdn.com/flex013/uploads/gatling2/original/2X/b/b148e0742de35c6280726cabf3ecd3de2d320f63.png) [@system](https://community.gatling.io/u/system)\ **Post date:** [July 8, 2023, 4:32pm UTC](https://community.gatling.io/t/gatling-appears-to-be-hijacking-stdout-logging/8012/3 "2023-07-08T16:32:21Z")
Closed on July 8, 2023, 4:32pm UTC This topic was automatically closed 30 days after the last reply. New replies are no longer allowed.