Open kami619 opened 2 weeks ago
ahus1
commented
2 weeks ago @kami619 - can you please provide the output of the Gatling run on the console? Maybe by running the Gatling test locally and not on an EC2 instance when triggering the failures? IMHO this could give additional insights on what errors were triggered, and it would probably be the first things asked for when opening an issue upstream.
kami619
commented
2 weeks ago @ahus1 It goes beyond the specified 600s in the run duration and gets stuck here.
================================================================================
2024-08-30 14:39:54 GMT 1765s elapsed
---- Requests ------------------------------------------------------------------
> Global (OK=102452 KO=2091 )
> Browser to Log In Endpoint (OK=28413 KO=2087 )
> Browser posts correct credentials (OK=24681 KO=2 )
> Exchange Code (OK=24679 KO=2 )
> Browser logout (OK=24679 KO=0 )
---- Errors --------------------------------------------------------------------
> j.n.c.ClosedChannelException 2072 (99.09%)
> j.i.IOException: Premature close 17 ( 0.81%)
> status.find.is(200), but actually found 400 2 ( 0.10%)
---- Authentication - Authorization Code Username/Password ---------------------
[################################################################----------] 87%
waiting: 0 / active: 3730 / done: 26770
================================================================================full log:
INFO: Running benchmark in single-run mode.
INFO: Running benchmark with users-per-sec=50.0, result output will be available in: /opt/keycloak-benchmark-0.14-SNAPSHOT/bin/../results/
14:10:27.650 [INFO ] a.e.s.Slf4jLogger - Slf4jLogger started
==========================================================
Target servers: [https://XXXXXXXXX.dualstack.awsglobalaccelerator.com]
Scenario:
Name: keycloak.scenario.authentication.AuthorizationCode
Population:
realms: 1
users-per-realm: 20000
clients-per-realm: 1
realm-name: realm-0
username: Not defined
user-password: Not defined
Runtime:
users-per-sec: 50.0 (Open Workload Model)
ramp-up: 20
warm-up: 0
measurement: 600
user-think-time: 0
refresh-token-period: 0
Service Level Agreements:
Max Error Percentage: 0.001
Max Mean Response Time: 300
Timestamps:
Start: 14:10:28
Warm-Up Start: 14:10:48
...skipping...
> j.i.IOException: Premature close 17 ( 0.81%)
> status.find.is(200), but actually found 400 2 ( 0.10%)
---- Authentication - Authorization Code Username/Password ---------------------
[################################################################----------] 87%
waiting: 0 / active: 3730 / done: 26770
================================================================================
================================================================================
2024-08-30 14:39:49 GMT 1760s elapsed
---- Requests ------------------------------------------------------------------
> Global (OK=102452 KO=2091 )
> Browser to Log In Endpoint (OK=28413 KO=2087 )
> Browser posts correct credentials (OK=24681 KO=2 )
> Exchange Code (OK=24679 KO=2 )
> Browser logout (OK=24679 KO=0 )
---- Errors --------------------------------------------------------------------
> j.n.c.ClosedChannelException 2072 (99.09%)
> j.i.IOException: Premature close 17 ( 0.81%)
> status.find.is(200), but actually found 400 2 ( 0.10%)
---- Authentication - Authorization Code Username/Password ---------------------
[################################################################----------] 87%
waiting: 0 / active: 3730 / done: 26770
================================================================================
...skipping...
> j.i.IOException: Premature close 17 ( 0.81%)
> status.find.is(200), but actually found 400 2 ( 0.10%)
---- Authentication - Authorization Code Username/Password ---------------------
[################################################################----------] 87%
waiting: 0 / active: 3730 / done: 26770
================================================================================
================================================================================
2024-08-30 14:39:49 GMT 1760s elapsed
---- Requests ------------------------------------------------------------------
> Global (OK=102452 KO=2091 )
> Browser to Log In Endpoint (OK=28413 KO=2087 )
> Browser posts correct credentials (OK=24681 KO=2 )
> Exchange Code (OK=24679 KO=2 )
> Browser logout (OK=24679 KO=0 )
---- Errors --------------------------------------------------------------------
> j.n.c.ClosedChannelException 2072 (99.09%)
> j.i.IOException: Premature close 17 ( 0.81%)
> status.find.is(200), but actually found 400 2 ( 0.10%)
---- Authentication - Authorization Code Username/Password ---------------------
[################################################################----------] 87%
waiting: 0 / active: 3730 / done: 26770
================================================================================
...skipping...
> j.i.IOException: Premature close 17 ( 0.81%)
> status.find.is(200), but actually found 400 2 ( 0.10%)
---- Authentication - Authorization Code Username/Password ---------------------
[################################################################----------] 87%
waiting: 0 / active: 3730 / done: 26770
================================================================================
================================================================================
2024-08-30 14:39:49 GMT 1760s elapsed
---- Requests ------------------------------------------------------------------
> Global (OK=102452 KO=2091 )
> Browser to Log In Endpoint (OK=28413 KO=2087 )
> Browser posts correct credentials (OK=24681 KO=2 )
> Exchange Code (OK=24679 KO=2 )
> Browser logout (OK=24679 KO=0 )
---- Errors --------------------------------------------------------------------
> j.n.c.ClosedChannelException 2072 (99.09%)
> j.i.IOException: Premature close 17 ( 0.81%)
> status.find.is(200), but actually found 400 2 ( 0.10%)
---- Authentication - Authorization Code Username/Password ---------------------
[################################################################----------] 87%
waiting: 0 / active: 3730 / done: 26770
================================================================================
...skipping...
> j.i.IOException: Premature close 17 ( 0.81%)
> status.find.is(200), but actually found 400 2 ( 0.10%)
---- Authentication - Authorization Code Username/Password ---------------------
[################################################################----------] 87%
waiting: 0 / active: 3730 / done: 26770
================================================================================
================================================================================
2024-08-30 14:39:49 GMT 1760s elapsed
---- Requests ------------------------------------------------------------------
> Global (OK=102452 KO=2091 )
> Browser to Log In Endpoint (OK=28413 KO=2087 )
> Browser posts correct credentials (OK=24681 KO=2 )
> Exchange Code (OK=24679 KO=2 )
> Browser logout (OK=24679 KO=0 )
---- Errors --------------------------------------------------------------------
> j.n.c.ClosedChannelException 2072 (99.09%)
> j.i.IOException: Premature close 17 ( 0.81%)
> status.find.is(200), but actually found 400 2 ( 0.10%)
---- Authentication - Authorization Code Username/Password ---------------------
[################################################################----------] 87%
waiting: 0 / active: 3730 / done: 26770
================================================================================
...skipping...
> j.i.IOException: Premature close 17 ( 0.81%)
> status.find.is(200), but actually found 400 2 ( 0.10%)
---- Authentication - Authorization Code Username/Password ---------------------
[################################################################----------] 87%
waiting: 0 / active: 3730 / done: 26770
================================================================================
================================================================================
2024-08-30 14:39:49 GMT 1760s elapsed
---- Requests ------------------------------------------------------------------
> Global (OK=102452 KO=2091 )
> Browser to Log In Endpoint (OK=28413 KO=2087 )
> Browser posts correct credentials (OK=24681 KO=2 )
> Exchange Code (OK=24679 KO=2 )
> Browser logout (OK=24679 KO=0 )
---- Errors --------------------------------------------------------------------
> j.n.c.ClosedChannelException 2072 (99.09%)
> j.i.IOException: Premature close 17 ( 0.81%)
> status.find.is(200), but actually found 400 2 ( 0.10%)
---- Authentication - Authorization Code Username/Password ---------------------
[################################################################----------] 87%
waiting: 0 / active: 3730 / done: 26770
================================================================================
...skipping...
> j.i.IOException: Premature close 17 ( 0.81%)
> status.find.is(200), but actually found 400 2 ( 0.10%)
---- Authentication - Authorization Code Username/Password ---------------------
[################################################################----------] 87%
waiting: 0 / active: 3730 / done: 26770
================================================================================
================================================================================
2024-08-30 14:39:49 GMT 1760s elapsed
---- Requests ------------------------------------------------------------------
> Global (OK=102452 KO=2091 )
> Browser to Log In Endpoint (OK=28413 KO=2087 )
> Browser posts correct credentials (OK=24681 KO=2 )
> Exchange Code (OK=24679 KO=2 )
> Browser logout (OK=24679 KO=0 )
---- Errors --------------------------------------------------------------------
> j.n.c.ClosedChannelException 2072 (99.09%)
> j.i.IOException: Premature close 17 ( 0.81%)
> status.find.is(200), but actually found 400 2 ( 0.10%)
---- Authentication - Authorization Code Username/Password ---------------------
[################################################################----------] 87%
waiting: 0 / active: 3730 / done: 26770
================================================================================
...skipping...
> j.i.IOException: Premature close 17 ( 0.81%)
> status.find.is(200), but actually found 400 2 ( 0.10%)
---- Authentication - Authorization Code Username/Password ---------------------
[################################################################----------] 87%
waiting: 0 / active: 3730 / done: 26770
================================================================================
================================================================================
2024-08-30 14:39:54 GMT 1765s elapsed
---- Requests ------------------------------------------------------------------
> Global (OK=102452 KO=2091 )
> Browser to Log In Endpoint (OK=28413 KO=2087 )
> Browser posts correct credentials (OK=24681 KO=2 )
> Exchange Code (OK=24679 KO=2 )
> Browser logout (OK=24679 KO=0 )
---- Errors --------------------------------------------------------------------
> j.n.c.ClosedChannelException 2072 (99.09%)
> j.i.IOException: Premature close 17 ( 0.81%)
> status.find.is(200), but actually found 400 2 ( 0.10%)
---- Authentication - Authorization Code Username/Password ---------------------
[################################################################----------] 87%
waiting: 0 / active: 3730 / done: 26770
================================================================================
Describe the bug
When we execute the Ansible playbooks and run the kcb.sh script on the EC2 load runners, once the test execution is done, the playbook should consolidate the gatling report in the last phase.
However, when this playbook is run against a Keycloak K8s cluster with a high CPU utilization, the JVM process of the Gatling application seems to be waiting indefinitely and the job only times out after the 60 min timeout configured inside the Ansible playbook.
Version
keycloak-benchmark latest main
Expected behavior
The Gatling should run and complete successfully irrespective of the Application Under Test behavior.
Actual behavior
It gets stuck in the last phase of the Gatling load test and doesn't finish independently.
How to Reproduce?
./aws_ec2.sh create eu-west-1./benchmark.sh eu-west-1 --scenario=keycloak.scenario.authentication.AuthorizationCode --server-url=<KEYCLOAK_URL> --realm-name=realm-0 --users-per-sec=150 --ramp-up=20 --logout-percentage=100 --measurement=600 --users-per-realm=20000 --sla-error-percentage=0.001PROJECT=<KEYCLOAK_NAMESPACE> ./kc-chaos.sh <RESULTS_DIR>Observe if the playbook finishes and collects the report in the last phase before the timeout is triggered for the Async polling.
Anything else?
Thread Dump from the stuck JVM process