--Task-- name: pkce-access-token-10 enabled: True class_name: GatlingTask source_name: overseer-0 source_namespace: >default< target_name: am target_namespace: >default< start: 0.0 stop: None timeout: not yet initialized for this Task as timeout was not explicitly defined, see updates below loop: False interval: None dependencies: [] wait_for: [] preceding_task: None options: {'testCase': 'am.PKCEauthGrantFlow', 'testMode': 'open', 'throughput': 10, 'duration': 3600, 'java-opts': '-Drealm=alpha -Duser_password=Pa_ssw0rd -Doauth2_client_id=endUserUIClient -Doauth2_redirect_uri=/enduser/appAuthHelperRedirect.html'} group_name: None Current dir: /mnt/disk1/xslou/workshop/lodestar-fork/pyrock 2025-03-19 15:11:28,268 INFO 2025-03-19 15:11:28,268 INFO [loop_until]: awk -F" " "{print NF}" <<< `kubectl --namespace=xlou --context=gke_engineeringpit_us-east1-d_xlou-cdm get pods --selector app=overseer-0 --output jsonpath={.items[*].metadata.name}` | grep 1 2025-03-19 15:11:28,268 INFO [loop_until]: (max_time=180, interval=10, expected_rc=[0] 2025-03-19 15:11:28,551 INFO [loop_until]: Function succeeded after 0s (rc=0) - expected number of elements found 2025-03-19 15:11:28,552 INFO [loop_until]: OK (rc = 0) 2025-03-19 15:11:28,552 DEBUG --- stdout --- 2025-03-19 15:11:28,552 DEBUG overseer-0-59c948f569-rgrkv 2025-03-19 15:11:28,552 DEBUG --- stderr --- 2025-03-19 15:11:28,552 DEBUG 2025-03-19 15:11:28,552 INFO Lodestar assumed that full stack is deployed so will set all products host URLs in Gatling system properties 2025-03-19 15:11:28 - INFO: Timeout for this Task has changed to 1h 12m (4320 seconds) 2025-03-19 15:11:28 - INFO: timeout was calculated based on simulation duration parameter Pod log file : /results/orders/pkce-access-token-10/stdout.txt Pod log : /results/orders/pkce-access-token-10 2025-03-19 15:11:29 - INFO: Get overseer pod resources requests memory 2025-03-19 15:11:29,118 INFO 2025-03-19 15:11:29,118 INFO [loop_until]: kubectl --namespace=xlou --context=gke_engineeringpit_us-east1-d_xlou-cdm get pods overseer-0-59c948f569-rgrkv --output jsonpath={.spec.containers[].resources.requests.memory} 2025-03-19 15:11:29,118 INFO [loop_until]: (max_time=180, interval=5, expected_rc=[0] 2025-03-19 15:11:29,419 INFO [loop_until]: OK (rc = 0) 2025-03-19 15:11:29,419 DEBUG --- stdout --- 2025-03-19 15:11:29,419 DEBUG 8Gi 2025-03-19 15:11:29,419 DEBUG --- stderr --- 2025-03-19 15:11:29,419 DEBUG ________________________________________________________________________________ [2025-03-19 15:11:29] pkce-access-token-10 print_command : Display the command to be forwarded to overseer as an order ________________________________________________________________________________ /lodestar/lodestar.py perf run-gatling --simulation-class="com.forgerock.pyrock.Loadtest" --run-description="am.PKCEauthGrantFlow@perf-200m" --results-folder="/results/gatling/pkce-access-token-10" --no-reports --simulation-jvm-args="-XX:+ExitOnOutOfMemoryError -Xmx8G" --simulation-system-properties="-Dam_host=openam-perf-200m.forgeblocks.com -Dam_oauth2_scope=openid^fr:idm:* -DamadminPassword=**** -DamadminUsername=xiaosong.lou@pingidentity.com -Dduration=3600 -Didc=true -Didm_host=openam-perf-200m.forgeblocks.com -Dlogin_cookie=15892ffd844ef80 -Dnum_users=50000000 -Doauth2_client_id=endUserUIClient -Doauth2_redirect_uri=/enduser/appAuthHelperRedirect.html -Drealm=alpha -DtestCase=am.PKCEauthGrantFlow -DtestMode=open -Dthroughput=10 -Duser_password=**** ________________________________________________________________________________ [2025-03-19 15:11:29] pkce-access-token-10 create_order : Create order for overseer with the command to run ________________________________________________________________________________ Order file: /mnt/disk1/xslou/workshop/lodestar-fork/results/pyrock/idc_access_token/07_Scenario_PKCEAccessToken/01_pkce-access-token-10/order.json { "name": "pkce-access-token-10", "command": " /lodestar/lodestar.py perf run-gatling --simulation-class=\"com.forgerock.pyrock.Loadtest\" --run-description=\"am.PKCEauthGrantFlow@perf-200m\" --results-folder=\"/results/gatling/pkce-access-token-10\" --no-reports --simulation-jvm-args=\"-XX:+ExitOnOutOfMemoryError -Xmx8G\" --simulation-system-properties=\"-Dam_host=openam-perf-200m.forgeblocks.com -Dam_oauth2_scope=openid^fr:idm:* -DamadminPassword=**** -DamadminUsername=xiaosong.lou@pingidentity.com -Dduration=3600 -Didc=true -Didm_host=openam-perf-200m.forgeblocks.com -Dlogin_cookie=15892ffd844ef80 -Dnum_users=50000000 -Doauth2_client_id=endUserUIClient -Doauth2_redirect_uri=/enduser/appAuthHelperRedirect.html -Drealm=alpha -DtestCase=am.PKCEauthGrantFlow -DtestMode=open -Dthroughput=10 -Duser_password=Pa_ssw0rd\"", "out-dir": "/results/orders/pkce-access-token-10" } ________________________________________________________________________________ [2025-03-19 15:11:29] pkce-access-token-10 loop_until_ready : Wait for preceding task to finish if it uses same Overseer as a source, then loop for max_time until Overseer pod status is READY to accept order :param max_time: periodically check overseer status for this many seconds at maximum :param interval: interval between two periodical checks :return: ________________________________________________________________________________ 2025-03-19 15:11:29,426 INFO 2025-03-19 15:11:29,426 INFO [loop_until]: curl --insecure https://overseer-0.xlou.iam.xlou-cdm.engineeringpit.com/orders/status.txt | grep "WAITING" 2025-03-19 15:11:29,426 INFO [loop_until]: (max_time=300, interval=5, expected_rc=[0] 2025-03-19 15:11:29,726 INFO [loop_until]: Function succeeded after 0s (rc=0) - expected pattern found 2025-03-19 15:11:29,726 INFO [loop_until]: OK (rc = 0) 2025-03-19 15:11:29,726 DEBUG --- stdout --- 2025-03-19 15:11:29,726 DEBUG WAITING 2025-03-19 15:11:29,726 DEBUG --- stderr --- 2025-03-19 15:11:29,726 DEBUG % Total % Received % Xferd Average Speed Time Time Time Current Dload Upload Total Spent Left Speed 0 0 0 0 0 0 0 0 --:--:-- --:--:-- --:--:-- 0 100 7 100 7 0 0 24 0 --:--:-- --:--:-- --:--:-- 24 ________________________________________________________________________________ [2025-03-19 15:11:29] pkce-access-token-10 start_order : Send the order to the overseer pod ________________________________________________________________________________ 2025-03-19 15:11:29,727 INFO 2025-03-19 15:11:29,727 INFO [loop_until]: awk -F" " "{print NF}" <<< `kubectl --namespace=xlou --context=gke_engineeringpit_us-east1-d_xlou-cdm get pods --selector app=overseer-0 --output jsonpath={.items[*].metadata.name}` | grep 1 2025-03-19 15:11:29,727 INFO [loop_until]: (max_time=180, interval=10, expected_rc=[0] 2025-03-19 15:11:30,002 INFO [loop_until]: Function succeeded after 0s (rc=0) - expected number of elements found 2025-03-19 15:11:30,003 INFO [loop_until]: OK (rc = 0) 2025-03-19 15:11:30,003 DEBUG --- stdout --- 2025-03-19 15:11:30,003 DEBUG overseer-0-59c948f569-rgrkv 2025-03-19 15:11:30,003 DEBUG --- stderr --- 2025-03-19 15:11:30,003 DEBUG 2025-03-19 15:11:30,003 INFO 2025-03-19 15:11:30,003 INFO [loop_until]: kubectl --namespace=xlou --context=gke_engineeringpit_us-east1-d_xlou-cdm cp /mnt/disk1/xslou/workshop/lodestar-fork/results/pyrock/idc_access_token/07_Scenario_PKCEAccessToken/01_pkce-access-token-10/order.json overseer-0-59c948f569-rgrkv:/results/orders/order.json 2025-03-19 15:11:30,003 INFO [loop_until]: (max_time=180, interval=5, expected_rc=[0] 2025-03-19 15:11:31,364 INFO [loop_until]: OK (rc = 0) 2025-03-19 15:11:31,364 DEBUG --- stdout --- 2025-03-19 15:11:31,364 DEBUG 2025-03-19 15:11:31,364 DEBUG --- stderr --- 2025-03-19 15:11:31,364 DEBUG Order has been successfully forwarded to overseer 2025-03-19 15:11:31 - INFO: Check if Gatling simulation started successfully 2025-03-19 15:11:31,365 INFO 2025-03-19 15:11:31,365 INFO [loop_until]: kubectl --namespace=xlou --context=gke_engineeringpit_us-east1-d_xlou-cdm exec overseer-0-59c948f569-rgrkv -- head --lines 5000 /results/orders/pkce-access-token-10/stdout.txt | grep "Simulation com.forgerock.pyrock.Loadtest started..." 2025-03-19 15:11:31,365 INFO [loop_until]: (max_time=300, interval=5, expected_rc=[0] 2025-03-19 15:11:32,124 INFO [loop_until]: Function succeeded after 0s (rc=0) - failed to find expected output: Simulation com.forgerock.pyrock.Loadtest started... - retry 2025-03-19 15:11:37,848 INFO [loop_until]: Function succeeded after 6s (rc=0) - failed to find expected output: Simulation com.forgerock.pyrock.Loadtest started... - retry 2025-03-19 15:11:43,572 INFO [loop_until]: Function succeeded after 12s (rc=0) - failed to find expected output: Simulation com.forgerock.pyrock.Loadtest started... - retry 2025-03-19 15:11:49,294 INFO [loop_until]: Function succeeded after 17s (rc=0) - expected pattern found 2025-03-19 15:11:49,294 INFO [loop_until]: OK (rc = 0) 2025-03-19 15:11:49,294 DEBUG --- stdout --- 2025-03-19 15:11:49,294 DEBUG 2025-03-19 15:11:32,139 INFO pom.xml and Gatling Scala files copied from /home/jenkins/lodestar/pyrock/shared/clients/gatling to temporary folder /tmp/tmp_d7d5sp3 2025-03-19 15:11:32,142 INFO Running Gatling simulation with command: mvn gatling:test --batch-mode -Dgatling.simulationClass="com.forgerock.pyrock.Loadtest" -Dgatling.runDescription="..." -Dgatling.resultsFolder="/results/gatling/pkce-access-token-10" -Dgatling.noReports=true -Dgatling.jvmArgs="-XX:+ExitOnOutOfMemoryError,-Xmx8G" -Dgatling.propagateSystemProperties=true -Dam_host=openam-perf-200m.forgeblocks.com -Dam_oauth2_scope=openid^fr:idm:* -DamadminPassword=**** -DamadminUsername=xiaosong.lou@pingidentity.com -Dduration=3600 -Didc=true -Didm_host=openam-perf-200m.forgeblocks.com -Dlogin_cookie=15892ffd844ef80 -Dnum_users=50000000 -Doauth2_client_id=endUserUIClient -Doauth2_redirect_uri=/enduser/appAuthHelperRedirect.html -Drealm=alpha -DtestCase=am.PKCEauthGrantFlow -DtestMode=open -Dthroughput=10 -Duser_password=**** [INFO] Scanning for projects... [INFO] [INFO] -----------< com.forgerock.pyrock:pyrock-gatling-simulation >----------- [INFO] Building pyrock-gatling-simulation 3.12.0 [INFO] from pom.xml [INFO] --------------------------------[ jar ]--------------------------------- [INFO] [INFO] >>> gatling:4.9.6:test (default-cli) > test-compile @ pyrock-gatling-simulation >>> [INFO] [INFO] --- resources:3.3.1:resources (default-resources) @ pyrock-gatling-simulation --- [INFO] skip non existing resourceDirectory /tmp/tmp_d7d5sp3/src/main/resources [INFO] [INFO] --- compiler:3.13.0:compile (default-compile) @ pyrock-gatling-simulation --- [INFO] No sources to compile [INFO] [INFO] --- resources:3.3.1:testResources (default-testResources) @ pyrock-gatling-simulation --- [INFO] Copying 2 resources from src/test/resources to target/test-classes [INFO] [INFO] --- compiler:3.13.0:testCompile (default-testCompile) @ pyrock-gatling-simulation --- [INFO] Nothing to compile - all classes are up to date. [INFO] [INFO] --- scala:4.9.2:testCompile (default) @ pyrock-gatling-simulation --- [INFO] compiling 38 Scala sources to /tmp/tmp_d7d5sp3/target/test-classes ... [INFO] compile in 8.8 s [INFO] [INFO] <<< gatling:4.9.6:test (default-cli) < test-compile @ pyrock-gatling-simulation <<< [INFO] [INFO] [INFO] --- gatling:4.9.6:test (default-cli) @ pyrock-gatling-simulation --- [INFO] Running simulation com.forgerock.pyrock.Loadtest. Gatling 3.13.5 is available! (you're using 3.12.0) System property think_time_multiplier not set. No think time emulation will be done in the simulation. Simulation com.forgerock.pyrock.Loadtest started... 2025-03-19 15:11:49,294 DEBUG --- stderr --- 2025-03-19 15:11:49,294 DEBUG ________________________________________________________________________________ [2025-03-19 15:11:49] pkce-access-token-10 wait_stop_by_itself : Wait for the order to stop by itself ________________________________________________________________________________ Task may stop by itself (no stop defined in configuration file), wait until overseer ends the order - timeout is 1h 12m. Waiting for status (curl --fail --insecure https://overseer-0.xlou.iam.xlou-cdm.engineeringpit.com/orders/status.txt) == WAITING Order is running since 2m, retry Order is running since 4m, retry Order is running since 6m, retry Order is running since 8m 01s, retry Order is running since 10m 01s, retry Order is running since 12m 01s, retry Order is running since 14m 02s, retry Order is running since 16m 02s, retry Order is running since 18m 02s, retry Order is running since 20m 03s, retry Order is running since 22m 03s, retry Order is running since 24m 03s, retry Order is running since 26m 04s, retry Order is running since 28m 04s, retry Order is running since 30m 04s, retry Order is running since 32m 05s, retry Order is running since 34m 05s, retry Order is running since 36m 05s, retry Order is running since 38m 06s, retry Order is running since 40m 06s, retry Order is running since 42m 06s, retry Order is running since 44m 06s, retry Order is running since 46m 07s, retry Order is running since 48m 07s, retry Order is running since 50m 07s, retry Order is running since 52m 08s, retry Order is running since 54m 08s, retry Order is running since 56m 08s, retry Order is running since 58m 09s, retry PASS : Order stopped by itself after 1h and before timeout (1h 12m) ________________________________________________________________________________ [2025-03-19 16:11:58] pkce-access-token-10 stop_order : Stop the order on overseer pod ________________________________________________________________________________ 2025-03-19 16:11:58,619 INFO 2025-03-19 16:11:58,619 INFO [loop_until]: awk -F" " "{print NF}" <<< `kubectl --namespace=xlou --context=gke_engineeringpit_us-east1-d_xlou-cdm get pods --selector app=overseer-0 --output jsonpath={.items[*].metadata.name}` | grep 1 2025-03-19 16:11:58,619 INFO [loop_until]: (max_time=180, interval=10, expected_rc=[0] 2025-03-19 16:11:58,984 INFO [loop_until]: Function succeeded after 0s (rc=0) - expected number of elements found 2025-03-19 16:11:58,984 INFO [loop_until]: OK (rc = 0) 2025-03-19 16:11:58,984 DEBUG --- stdout --- 2025-03-19 16:11:58,984 DEBUG overseer-0-59c948f569-rgrkv 2025-03-19 16:11:58,984 DEBUG --- stderr --- 2025-03-19 16:11:58,984 DEBUG 2025-03-19 16:11:58,985 INFO 2025-03-19 16:11:58,985 INFO [loop_until]: kubectl --namespace=xlou --context=gke_engineeringpit_us-east1-d_xlou-cdm exec overseer-0-59c948f569-rgrkv -- rm -f /results/orders/order.json 2025-03-19 16:11:58,985 INFO [loop_until]: (max_time=180, interval=5, expected_rc=[0] 2025-03-19 16:11:59,775 INFO [loop_until]: OK (rc = 0) 2025-03-19 16:11:59,775 DEBUG --- stdout --- 2025-03-19 16:11:59,775 DEBUG 2025-03-19 16:11:59,775 DEBUG --- stderr --- 2025-03-19 16:11:59,775 DEBUG Order ran during 1h ________________________________________________________________________________ [2025-03-19 16:11:59] pkce-access-token-10 download_logs : Download individual order files ________________________________________________________________________________ 2025-03-19 16:11:59 - PASS: file already downloaded /mnt/disk1/xslou/workshop/lodestar-fork/results/pyrock/idc_access_token/07_Scenario_PKCEAccessToken/01_pkce-access-token-10/order.json 2025-03-19 16:11:59,776 INFO 2025-03-19 16:11:59,776 INFO [loop_until]: awk -F" " "{print NF}" <<< `kubectl --namespace=xlou --context=gke_engineeringpit_us-east1-d_xlou-cdm get pods --selector app=overseer-0 --output jsonpath={.items[*].metadata.name}` | grep 1 2025-03-19 16:11:59,776 INFO [loop_until]: (max_time=180, interval=10, expected_rc=[0] 2025-03-19 16:12:00,056 INFO [loop_until]: Function succeeded after 0s (rc=0) - expected number of elements found 2025-03-19 16:12:00,056 INFO [loop_until]: OK (rc = 0) 2025-03-19 16:12:00,056 DEBUG --- stdout --- 2025-03-19 16:12:00,056 DEBUG overseer-0-59c948f569-rgrkv 2025-03-19 16:12:00,056 DEBUG --- stderr --- 2025-03-19 16:12:00,056 DEBUG Checking pod: overseer-0-59c948f569-rgrkv for file exists, if not wait. 2025-03-19 16:12:00,057 INFO 2025-03-19 16:12:00,057 INFO [loop_until]: kubectl --namespace=xlou --context=gke_engineeringpit_us-east1-d_xlou-cdm exec overseer-0-59c948f569-rgrkv --stdin -- bash -c 'if [ -f "/results/orders/pkce-access-token-10/rc.txt" ]; then echo "/results/orders/pkce-access-token-10/rc.txt file found"; exit 0; else echo "/results/orders/pkce-access-token-10/rc.txt file not found"; exit 1; fi' | grep "/results/orders/pkce-access-token-10/rc.txt file found" 2025-03-19 16:12:00,057 INFO [loop_until]: (max_time=180, interval=5, expected_rc=[0] 2025-03-19 16:12:00,857 INFO [loop_until]: Function succeeded after 0s (rc=0) - expected pattern found 2025-03-19 16:12:00,857 INFO [loop_until]: OK (rc = 0) 2025-03-19 16:12:00,857 DEBUG --- stdout --- 2025-03-19 16:12:00,857 DEBUG /results/orders/pkce-access-token-10/rc.txt file found 2025-03-19 16:12:00,857 DEBUG --- stderr --- 2025-03-19 16:12:00,857 DEBUG 2025-03-19 16:12:00,857 INFO 2025-03-19 16:12:00,858 INFO [run_command]: kubectl --namespace=xlou --context=gke_engineeringpit_us-east1-d_xlou-cdm exec overseer-0-59c948f569-rgrkv --stdin -- du -k /results/orders/pkce-access-token-10/rc.txt 2025-03-19 16:12:01,664 INFO [run_command]: OK (rc = 0 - expected to be in [0]) 2025-03-19 16:12:01,664 DEBUG --- stdout --- 2025-03-19 16:12:01,664 DEBUG 4 /results/orders/pkce-access-token-10/rc.txt 2025-03-19 16:12:01,664 DEBUG --- stderr --- 2025-03-19 16:12:01,664 DEBUG 2025-03-19 16:12:01,664 INFO - Download file (size 4k) source : /results/orders/pkce-access-token-10/rc.txt @ overseer-0-59c948f569-rgrkv destination : /mnt/disk1/xslou/workshop/lodestar-fork/results/pyrock/idc_access_token/07_Scenario_PKCEAccessToken/01_pkce-access-token-10/rc.txt 2025-03-19 16:12:01,665 INFO 2025-03-19 16:12:01,665 INFO [loop_until]: kubectl --namespace=xlou --context=gke_engineeringpit_us-east1-d_xlou-cdm cp --retries=100 overseer-0-59c948f569-rgrkv:/results/orders/pkce-access-token-10/rc.txt /mnt/disk1/xslou/workshop/lodestar-fork/results/pyrock/idc_access_token/07_Scenario_PKCEAccessToken/01_pkce-access-token-10/rc.txt 2025-03-19 16:12:01,665 INFO [loop_until]: (max_time=-1, interval=5, expected_rc=[0] 2025-03-19 16:12:02,393 INFO [loop_until]: OK (rc = 0) 2025-03-19 16:12:02,393 DEBUG --- stdout --- 2025-03-19 16:12:02,393 DEBUG tar: Removing leading `/' from member names 2025-03-19 16:12:02,393 DEBUG --- stderr --- 2025-03-19 16:12:02,393 DEBUG 2025-03-19 16:12:02,393 INFO 2025-03-19 16:12:02,393 INFO [loop_until]: awk -F" " "{print NF}" <<< `kubectl --namespace=xlou --context=gke_engineeringpit_us-east1-d_xlou-cdm get pods --selector app=overseer-0 --output jsonpath={.items[*].metadata.name}` | grep 1 2025-03-19 16:12:02,393 INFO [loop_until]: (max_time=180, interval=10, expected_rc=[0] 2025-03-19 16:12:02,675 INFO [loop_until]: Function succeeded after 0s (rc=0) - expected number of elements found 2025-03-19 16:12:02,676 INFO [loop_until]: OK (rc = 0) 2025-03-19 16:12:02,676 DEBUG --- stdout --- 2025-03-19 16:12:02,676 DEBUG overseer-0-59c948f569-rgrkv 2025-03-19 16:12:02,676 DEBUG --- stderr --- 2025-03-19 16:12:02,676 DEBUG Checking pod: overseer-0-59c948f569-rgrkv for file exists, if not wait. 2025-03-19 16:12:02,677 INFO 2025-03-19 16:12:02,677 INFO [loop_until]: kubectl --namespace=xlou --context=gke_engineeringpit_us-east1-d_xlou-cdm exec overseer-0-59c948f569-rgrkv --stdin -- bash -c 'if [ -f "/results/orders/pkce-access-token-10/stderr.txt" ]; then echo "/results/orders/pkce-access-token-10/stderr.txt file found"; exit 0; else echo "/results/orders/pkce-access-token-10/stderr.txt file not found"; exit 1; fi' | grep "/results/orders/pkce-access-token-10/stderr.txt file found" 2025-03-19 16:12:02,677 INFO [loop_until]: (max_time=180, interval=5, expected_rc=[0] 2025-03-19 16:12:03,514 INFO [loop_until]: Function succeeded after 0s (rc=0) - expected pattern found 2025-03-19 16:12:03,514 INFO [loop_until]: OK (rc = 0) 2025-03-19 16:12:03,514 DEBUG --- stdout --- 2025-03-19 16:12:03,514 DEBUG /results/orders/pkce-access-token-10/stderr.txt file found 2025-03-19 16:12:03,514 DEBUG --- stderr --- 2025-03-19 16:12:03,514 DEBUG 2025-03-19 16:12:03,514 INFO 2025-03-19 16:12:03,515 INFO [run_command]: kubectl --namespace=xlou --context=gke_engineeringpit_us-east1-d_xlou-cdm exec overseer-0-59c948f569-rgrkv --stdin -- du -k /results/orders/pkce-access-token-10/stderr.txt 2025-03-19 16:12:04,325 INFO [run_command]: OK (rc = 0 - expected to be in [0]) 2025-03-19 16:12:04,325 DEBUG --- stdout --- 2025-03-19 16:12:04,325 DEBUG 0 /results/orders/pkce-access-token-10/stderr.txt 2025-03-19 16:12:04,325 DEBUG --- stderr --- 2025-03-19 16:12:04,325 DEBUG 2025-03-19 16:12:04,325 INFO - Download file (size 0k) source : /results/orders/pkce-access-token-10/stderr.txt @ overseer-0-59c948f569-rgrkv destination : /mnt/disk1/xslou/workshop/lodestar-fork/results/pyrock/idc_access_token/07_Scenario_PKCEAccessToken/01_pkce-access-token-10/stderr.txt 2025-03-19 16:12:04,326 INFO 2025-03-19 16:12:04,326 INFO [loop_until]: kubectl --namespace=xlou --context=gke_engineeringpit_us-east1-d_xlou-cdm cp --retries=100 overseer-0-59c948f569-rgrkv:/results/orders/pkce-access-token-10/stderr.txt /mnt/disk1/xslou/workshop/lodestar-fork/results/pyrock/idc_access_token/07_Scenario_PKCEAccessToken/01_pkce-access-token-10/stderr.txt 2025-03-19 16:12:04,326 INFO [loop_until]: (max_time=-1, interval=5, expected_rc=[0] 2025-03-19 16:12:05,075 INFO [loop_until]: OK (rc = 0) 2025-03-19 16:12:05,075 DEBUG --- stdout --- 2025-03-19 16:12:05,075 DEBUG tar: Removing leading `/' from member names 2025-03-19 16:12:05,075 DEBUG --- stderr --- 2025-03-19 16:12:05,075 DEBUG 2025-03-19 16:12:05,075 INFO 2025-03-19 16:12:05,075 INFO [loop_until]: awk -F" " "{print NF}" <<< `kubectl --namespace=xlou --context=gke_engineeringpit_us-east1-d_xlou-cdm get pods --selector app=overseer-0 --output jsonpath={.items[*].metadata.name}` | grep 1 2025-03-19 16:12:05,075 INFO [loop_until]: (max_time=180, interval=10, expected_rc=[0] 2025-03-19 16:12:05,356 INFO [loop_until]: Function succeeded after 0s (rc=0) - expected number of elements found 2025-03-19 16:12:05,356 INFO [loop_until]: OK (rc = 0) 2025-03-19 16:12:05,356 DEBUG --- stdout --- 2025-03-19 16:12:05,356 DEBUG overseer-0-59c948f569-rgrkv 2025-03-19 16:12:05,356 DEBUG --- stderr --- 2025-03-19 16:12:05,356 DEBUG Checking pod: overseer-0-59c948f569-rgrkv for file exists, if not wait. 2025-03-19 16:12:05,357 INFO 2025-03-19 16:12:05,357 INFO [loop_until]: kubectl --namespace=xlou --context=gke_engineeringpit_us-east1-d_xlou-cdm exec overseer-0-59c948f569-rgrkv --stdin -- bash -c 'if [ -f "/results/orders/pkce-access-token-10/stdout.txt" ]; then echo "/results/orders/pkce-access-token-10/stdout.txt file found"; exit 0; else echo "/results/orders/pkce-access-token-10/stdout.txt file not found"; exit 1; fi' | grep "/results/orders/pkce-access-token-10/stdout.txt file found" 2025-03-19 16:12:05,357 INFO [loop_until]: (max_time=180, interval=5, expected_rc=[0] 2025-03-19 16:12:06,167 INFO [loop_until]: Function succeeded after 0s (rc=0) - expected pattern found 2025-03-19 16:12:06,167 INFO [loop_until]: OK (rc = 0) 2025-03-19 16:12:06,167 DEBUG --- stdout --- 2025-03-19 16:12:06,167 DEBUG /results/orders/pkce-access-token-10/stdout.txt file found 2025-03-19 16:12:06,168 DEBUG --- stderr --- 2025-03-19 16:12:06,168 DEBUG 2025-03-19 16:12:06,168 INFO 2025-03-19 16:12:06,168 INFO [run_command]: kubectl --namespace=xlou --context=gke_engineeringpit_us-east1-d_xlou-cdm exec overseer-0-59c948f569-rgrkv --stdin -- du -k /results/orders/pkce-access-token-10/stdout.txt 2025-03-19 16:12:06,976 INFO [run_command]: OK (rc = 0 - expected to be in [0]) 2025-03-19 16:12:06,976 DEBUG --- stdout --- 2025-03-19 16:12:06,976 DEBUG 840 /results/orders/pkce-access-token-10/stdout.txt 2025-03-19 16:12:06,976 DEBUG --- stderr --- 2025-03-19 16:12:06,976 DEBUG 2025-03-19 16:12:06,976 INFO - Download file (size 840k) source : /results/orders/pkce-access-token-10/stdout.txt @ overseer-0-59c948f569-rgrkv destination : /mnt/disk1/xslou/workshop/lodestar-fork/results/pyrock/idc_access_token/07_Scenario_PKCEAccessToken/01_pkce-access-token-10/stdout.txt 2025-03-19 16:12:06,977 INFO 2025-03-19 16:12:06,977 INFO [loop_until]: kubectl --namespace=xlou --context=gke_engineeringpit_us-east1-d_xlou-cdm cp --retries=100 overseer-0-59c948f569-rgrkv:/results/orders/pkce-access-token-10/stdout.txt /mnt/disk1/xslou/workshop/lodestar-fork/results/pyrock/idc_access_token/07_Scenario_PKCEAccessToken/01_pkce-access-token-10/stdout.txt 2025-03-19 16:12:06,977 INFO [loop_until]: (max_time=-1, interval=5, expected_rc=[0] 2025-03-19 16:12:08,071 INFO [loop_until]: OK (rc = 0) 2025-03-19 16:12:08,071 DEBUG --- stdout --- 2025-03-19 16:12:08,071 DEBUG tar: Removing leading `/' from member names 2025-03-19 16:12:08,071 DEBUG --- stderr --- 2025-03-19 16:12:08,071 DEBUG ________________________________________________________________________________ [2025-03-19 16:12:08] pkce-access-token-10 show_cmd : Display order command ________________________________________________________________________________ 2025-03-19 16:12:08,072 INFO 2025-03-19 16:12:08,072 INFO [loop_until]: awk -F" " "{print NF}" <<< `kubectl --namespace=xlou --context=gke_engineeringpit_us-east1-d_xlou-cdm get pods --selector app=overseer-0 --output jsonpath={.items[*].metadata.name}` | grep 1 2025-03-19 16:12:08,072 INFO [loop_until]: (max_time=180, interval=10, expected_rc=[0] 2025-03-19 16:12:08,355 INFO [loop_until]: Function succeeded after 0s (rc=0) - expected number of elements found 2025-03-19 16:12:08,355 INFO [loop_until]: OK (rc = 0) 2025-03-19 16:12:08,355 DEBUG --- stdout --- 2025-03-19 16:12:08,355 DEBUG overseer-0-59c948f569-rgrkv 2025-03-19 16:12:08,355 DEBUG --- stderr --- 2025-03-19 16:12:08,355 DEBUG Checking pod: overseer-0-59c948f569-rgrkv for file exists, if not wait. 2025-03-19 16:12:08,356 INFO 2025-03-19 16:12:08,356 INFO [loop_until]: kubectl --namespace=xlou --context=gke_engineeringpit_us-east1-d_xlou-cdm exec overseer-0-59c948f569-rgrkv --stdin -- bash -c 'if [ -f "/results/orders/pkce-access-token-10/cmd.txt" ]; then echo "/results/orders/pkce-access-token-10/cmd.txt file found"; exit 0; else echo "/results/orders/pkce-access-token-10/cmd.txt file not found"; exit 1; fi' | grep "/results/orders/pkce-access-token-10/cmd.txt file found" 2025-03-19 16:12:08,356 INFO [loop_until]: (max_time=180, interval=5, expected_rc=[0] 2025-03-19 16:12:09,153 INFO [loop_until]: Function succeeded after 0s (rc=0) - expected pattern found 2025-03-19 16:12:09,153 INFO [loop_until]: OK (rc = 0) 2025-03-19 16:12:09,153 DEBUG --- stdout --- 2025-03-19 16:12:09,154 DEBUG /results/orders/pkce-access-token-10/cmd.txt file found 2025-03-19 16:12:09,154 DEBUG --- stderr --- 2025-03-19 16:12:09,154 DEBUG 2025-03-19 16:12:09,154 INFO 2025-03-19 16:12:09,154 INFO [run_command]: kubectl --namespace=xlou --context=gke_engineeringpit_us-east1-d_xlou-cdm exec overseer-0-59c948f569-rgrkv --stdin -- du -k /results/orders/pkce-access-token-10/cmd.txt 2025-03-19 16:12:09,963 INFO [run_command]: OK (rc = 0 - expected to be in [0]) 2025-03-19 16:12:09,963 DEBUG --- stdout --- 2025-03-19 16:12:09,963 DEBUG 4 /results/orders/pkce-access-token-10/cmd.txt 2025-03-19 16:12:09,963 DEBUG --- stderr --- 2025-03-19 16:12:09,963 DEBUG 2025-03-19 16:12:09,963 INFO - Download file (size 4k) source : /results/orders/pkce-access-token-10/cmd.txt @ overseer-0-59c948f569-rgrkv destination : /mnt/disk1/xslou/workshop/lodestar-fork/results/pyrock/idc_access_token/07_Scenario_PKCEAccessToken/01_pkce-access-token-10/cmd.txt 2025-03-19 16:12:09,964 INFO 2025-03-19 16:12:09,964 INFO [loop_until]: kubectl --namespace=xlou --context=gke_engineeringpit_us-east1-d_xlou-cdm cp --retries=100 overseer-0-59c948f569-rgrkv:/results/orders/pkce-access-token-10/cmd.txt /mnt/disk1/xslou/workshop/lodestar-fork/results/pyrock/idc_access_token/07_Scenario_PKCEAccessToken/01_pkce-access-token-10/cmd.txt 2025-03-19 16:12:09,964 INFO [loop_until]: (max_time=-1, interval=5, expected_rc=[0] 2025-03-19 16:12:10,742 INFO [loop_until]: OK (rc = 0) 2025-03-19 16:12:10,742 DEBUG --- stdout --- 2025-03-19 16:12:10,742 DEBUG tar: Removing leading `/' from member names 2025-03-19 16:12:10,742 DEBUG --- stderr --- 2025-03-19 16:12:10,742 DEBUG 2025-03-19 16:12:10,742 DEBUG [print_head_tail]: Input file /mnt/disk1/xslou/workshop/lodestar-fork/results/pyrock/idc_access_token/07_Scenario_PKCEAccessToken/01_pkce-access-token-10/cmd.txt is small (1 lines), printing all lines: 2025-03-19 16:12:10,742 INFO ----- output ----- /lodestar/lodestar.py perf run-gatling --simulation-class="com.forgerock.pyrock.Loadtest" --run-description="am.PKCEauthGrantFlow@perf-200m" --results-folder="/results/gatling/pkce-access-token-10" --no-reports --simulation-jvm-args="-XX:+ExitOnOutOfMemoryError -Xmx8G" --simulation-system-properties="-Dam_host=openam-perf-200m.forgeblocks.com -Dam_oauth2_scope=openid^fr:idm:* -DamadminPassword=M@ythe4th -DamadminUsername=xiaosong.lou@pingidentity.com -Dduration=3600 -Didc=true -Didm_host=openam-perf-200m.forgeblocks.com -Dlogin_cookie=15892ffd844ef80 -Dnum_users=50000000 -Doauth2_client_id=endUserUIClient -Doauth2_redirect_uri=/enduser/appAuthHelperRedirect.html -Drealm=alpha -DtestCase=am.PKCEauthGrantFlow -DtestMode=open -Dthroughput=10 -Duser_password=Pa_ssw0rd" ________________________________________________________________________________ [2025-03-19 16:12:10] pkce-access-token-10 show_rc : Display rc order ________________________________________________________________________________ 2025-03-19 16:12:10,743 DEBUG [print_head_tail]: Input file /mnt/disk1/xslou/workshop/lodestar-fork/results/pyrock/idc_access_token/07_Scenario_PKCEAccessToken/01_pkce-access-token-10/rc.txt is small (1 lines), printing all lines: 2025-03-19 16:12:10,743 INFO ----- output ----- CMD SUCCESS: command returns code 0 (expected [0, -9, 143, 137, -15]) ________________________________________________________________________________ [2025-03-19 16:12:10] pkce-access-token-10 show_stdout : Display stdout order ________________________________________________________________________________ 2025-03-19 16:12:10,744 DEBUG [print_head_tail]: Print head (100 lines) and tail (100 lines) of input file (/mnt/disk1/xslou/workshop/lodestar-fork/results/pyrock/idc_access_token/07_Scenario_PKCEAccessToken/01_pkce-access-token-10/stdout.txt is 13064 lines): 2025-03-19 16:12:10,746 INFO ----- output ----- 2025-03-19 15:11:32,139 INFO pom.xml and Gatling Scala files copied from /home/jenkins/lodestar/pyrock/shared/clients/gatling to temporary folder /tmp/tmp_d7d5sp3 2025-03-19 15:11:32,142 INFO Running Gatling simulation with command: mvn gatling:test --batch-mode -Dgatling.simulationClass="com.forgerock.pyrock.Loadtest" -Dgatling.runDescription="..." -Dgatling.resultsFolder="/results/gatling/pkce-access-token-10" -Dgatling.noReports=true -Dgatling.jvmArgs="-XX:+ExitOnOutOfMemoryError,-Xmx8G" -Dgatling.propagateSystemProperties=true -Dam_host=openam-perf-200m.forgeblocks.com -Dam_oauth2_scope=openid^fr:idm:* -DamadminPassword=**** -DamadminUsername=xiaosong.lou@pingidentity.com -Dduration=3600 -Didc=true -Didm_host=openam-perf-200m.forgeblocks.com -Dlogin_cookie=15892ffd844ef80 -Dnum_users=50000000 -Doauth2_client_id=endUserUIClient -Doauth2_redirect_uri=/enduser/appAuthHelperRedirect.html -Drealm=alpha -DtestCase=am.PKCEauthGrantFlow -DtestMode=open -Dthroughput=10 -Duser_password=**** [INFO] Scanning for projects... [INFO] [INFO] -----------< com.forgerock.pyrock:pyrock-gatling-simulation >----------- [INFO] Building pyrock-gatling-simulation 3.12.0 [INFO] from pom.xml [INFO] --------------------------------[ jar ]--------------------------------- [INFO] [INFO] >>> gatling:4.9.6:test (default-cli) > test-compile @ pyrock-gatling-simulation >>> [INFO] [INFO] --- resources:3.3.1:resources (default-resources) @ pyrock-gatling-simulation --- [INFO] skip non existing resourceDirectory /tmp/tmp_d7d5sp3/src/main/resources [INFO] [INFO] --- compiler:3.13.0:compile (default-compile) @ pyrock-gatling-simulation --- [INFO] No sources to compile [INFO] [INFO] --- resources:3.3.1:testResources (default-testResources) @ pyrock-gatling-simulation --- [INFO] Copying 2 resources from src/test/resources to target/test-classes [INFO] [INFO] --- compiler:3.13.0:testCompile (default-testCompile) @ pyrock-gatling-simulation --- [INFO] Nothing to compile - all classes are up to date. [INFO] [INFO] --- scala:4.9.2:testCompile (default) @ pyrock-gatling-simulation --- [INFO] compiling 38 Scala sources to /tmp/tmp_d7d5sp3/target/test-classes ... [INFO] compile in 8.8 s [INFO] [INFO] <<< gatling:4.9.6:test (default-cli) < test-compile @ pyrock-gatling-simulation <<< [INFO] [INFO] [INFO] --- gatling:4.9.6:test (default-cli) @ pyrock-gatling-simulation --- [INFO] Running simulation com.forgerock.pyrock.Loadtest. Gatling 3.13.5 is available! (you're using 3.12.0) System property think_time_multiplier not set. No think time emulation will be done in the simulation. Simulation com.forgerock.pyrock.Loadtest started... ================================================================================ 2025-03-19 15:11:50 GMT 5s elapsed ---- Requests ------------------------------------------------------------------ > Global (OK=14 KO=0 ) > restLoginInitiate (OK=4 KO=0 ) > restLoginUsernamePasswordCallback (OK=4 KO=0 ) > User Authorize PKCE stage (OK=3 KO=0 ) > User AccessToken PKCE stage (OK=3 KO=0 ) ---- am.PKCEauthGrantFlow ------------------------------------------------------ [- ] 0% waiting: 36404 / active: 1 / done: 3 ================================================================================ ================================================================================ 2025-03-19 15:11:55 GMT 10s elapsed ---- Requests ------------------------------------------------------------------ > Global (OK=64 KO=0 ) > restLoginInitiate (OK=16 KO=0 ) > restLoginUsernamePasswordCallback (OK=16 KO=0 ) > User Authorize PKCE stage (OK=16 KO=0 ) > User AccessToken PKCE stage (OK=16 KO=0 ) ---- am.PKCEauthGrantFlow ------------------------------------------------------ [ ] 0% waiting: 36392 / active: 0 / done: 16 ================================================================================ ================================================================================ 2025-03-19 15:12:00 GMT 15s elapsed ---- Requests ------------------------------------------------------------------ > Global (OK=146 KO=0 ) > restLoginInitiate (OK=37 KO=0 ) > restLoginUsernamePasswordCallback (OK=37 KO=0 ) > User Authorize PKCE stage (OK=36 KO=0 ) > User AccessToken PKCE stage (OK=36 KO=0 ) ---- am.PKCEauthGrantFlow ------------------------------------------------------ [- ] 0% waiting: 36371 / active: 1 / done: 36 ================================================================================ ================================================================================ 2025-03-19 15:12:05 GMT 20s elapsed ---- Requests ------------------------------------------------------------------ > Global (OK=262 KO=0 ) > restLoginInitiate (OK=66 KO=0 ) > restLoginUsernamePasswordCallback (OK=66 KO=0 ) > User Authorize PKCE stage (OK=65 KO=0 ) > User AccessToken PKCE stage (OK=65 KO=0 ) ---- am.PKCEauthGrantFlow ------------------------------------------------------ [- ] 0% waiting: 36342 / active: 1 / done: 65 ================================================================================ ================================================================================ 2025-03-19 15:12:10 GMT 25s elapsed ---- Requests ------------------------------------------------------------------ > Global (OK=412 KO=0 ) [...] > Global (OK=143898 KO=6 ) > restLoginInitiate (OK=35976 KO=5 ) > restLoginUsernamePasswordCallback (OK=35975 KO=0 ) > User Authorize PKCE stage (OK=35974 KO=0 ) > User AccessToken PKCE stage (OK=35973 KO=1 ) ---- Errors -------------------------------------------------------------------- > status.find.is(200), but actually found 502 5 (83.33%) > status.find.in([200, 209], 304), found 502 1 (16.67%) ---- am.PKCEauthGrantFlow ------------------------------------------------------ [#########################################################################-] 98% waiting: 426 / active: 3 / done: 35979 ================================================================================ ================================================================================ 2025-03-19 16:11:40 GMT 3595s elapsed ---- Requests ------------------------------------------------------------------ > Global (OK=144135 KO=6 ) > restLoginInitiate (OK=36034 KO=5 ) > restLoginUsernamePasswordCallback (OK=36034 KO=0 ) > User Authorize PKCE stage (OK=36034 KO=0 ) > User AccessToken PKCE stage (OK=36033 KO=1 ) ---- Errors -------------------------------------------------------------------- > status.find.is(200), but actually found 502 5 (83.33%) > status.find.in([200, 209], 304), found 502 1 (16.67%) ---- am.PKCEauthGrantFlow ------------------------------------------------------ [######################################################################### ] 98% waiting: 369 / active: 0 / done: 36039 ================================================================================ ================================================================================ 2025-03-19 16:11:45 GMT 3599s elapsed ---- Requests ------------------------------------------------------------------ > Global (OK=144336 KO=6 ) > restLoginInitiate (OK=36086 KO=5 ) > restLoginUsernamePasswordCallback (OK=36085 KO=0 ) > User Authorize PKCE stage (OK=36083 KO=0 ) > User AccessToken PKCE stage (OK=36082 KO=1 ) ---- Errors -------------------------------------------------------------------- > status.find.is(200), but actually found 502 5 (83.33%) > status.find.in([200, 209], 304), found 502 1 (16.67%) ---- am.PKCEauthGrantFlow ------------------------------------------------------ [#########################################################################-] 99% waiting: 316 / active: 4 / done: 36088 ================================================================================ ================================================================================ 2025-03-19 16:11:45 GMT 3600s elapsed ---- Requests ------------------------------------------------------------------ > Global (OK=144336 KO=6 ) > restLoginInitiate (OK=36086 KO=5 ) > restLoginUsernamePasswordCallback (OK=36085 KO=0 ) > User Authorize PKCE stage (OK=36083 KO=0 ) > User AccessToken PKCE stage (OK=36082 KO=1 ) ---- Errors -------------------------------------------------------------------- > status.find.is(200), but actually found 502 5 (83.33%) > status.find.in([200, 209], 304), found 502 1 (16.67%) ---- am.PKCEauthGrantFlow ------------------------------------------------------ [#########################################################################-] 99% waiting: 316 / active: 4 / done: 36088 ================================================================================ 16:11:45.233 [DEBUG] i.g.h.e.r.DefaultStatsProcessor - Request 'restLoginInitiate' failed for user 36092: j.i.IOException: Premature close 16:11:45.233 [DEBUG] i.g.h.e.r.DefaultStatsProcessor - >>>>>>>>>>>>>>>>>>>>>>>>>> Request: restLoginInitiate: KO j.i.IOException: Premature close ========================= Session: Session(am.PKCEauthGrantFlow,36092,HashMap(gatling.http.cache.baseUrl -> https://openam-perf-200m.forgeblocks.com:443, username -> user.36008438, gatling.http.ssl.sslContexts -> io.gatling.http.util.SslContexts@7a6c37cd, fake-user-agent -> Mozilla/5.0 (Linux; Android 6.0; Nexus 5 Build/MRA58N) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/90.0.4430.85 Mobile Safari/537.36, password -> Pa_ssw0rd, fake-ip -> 227.248.225.112, gatling.http.cache.dns -> io.gatling.http.resolver.ShufflingNameResolver@134ab437),KO,List(),io.gatling.core.protocol.ProtocolComponentsRegistry$$Lambda$787/0x00007db4dc67fc28@70bf3e21,io.netty.channel.epoll.EpollEventLoop@30f5a68a) ========================= HTTP request: POST https://openam-perf-200m.forgeblocks.com/am/json/realms/root/realms/alpha/authenticate headers: content-type: application/json Accept-API-Version: resource=2.0, protocol=1.0 accept: application/json X-Forwarded-For: 227.248.225.112 User-Agent: Mozilla/5.0 (Linux; Android 6.0; Nexus 5 Build/MRA58N) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/90.0.4430.85 Mobile Safari/537.36 host: openam-perf-200m.forgeblocks.com content-length: 0 body:StringChunksRequestBody{charset=UTF-8, content=} ========================= HTTP response: <<<<<<<<<<<<<<<<<<<<<<<<< 16:11:45.233 [ERROR] i.g.c.a.b.SessionHookBuilder$$anon$1 - 'hook-20' crashed with 'j.u.NoSuchElementException: No attribute named 'callbacks' is defined', forwarding to the next one [INFO] ------------------------------------------------------------------------ [INFO] BUILD SUCCESS [INFO] ------------------------------------------------------------------------ [INFO] Total time: 01:00 h [INFO] Finished at: 2025-03-19T16:11:45Z [INFO] ------------------------------------------------------------------------ 2025-03-19 16:11:45,287 INFO Gatling simulation run ended successfully 2025-03-19 16:11:45,287 DEBUG No archive name provided. No archive will be created ________________________________________________________________________________ [2025-03-19 16:12:10] pkce-access-token-10 show_stderr : Display stderr order ________________________________________________________________________________ 2025-03-19 16:12:10,746 DEBUG [print_head_tail]: Input file /mnt/disk1/xslou/workshop/lodestar-fork/results/pyrock/idc_access_token/07_Scenario_PKCEAccessToken/01_pkce-access-token-10/stderr.txt is small (0 lines), printing all lines: 2025-03-19 16:12:10,746 INFO ----- output ----- ________________________________________________________________________________ [2025-03-19 16:12:10] pkce-access-token-10 check_rc_and_logs : Check order's outputs ________________________________________________________________________________ CMD SUCCESS: command returns code 0 (expected [0, -9, 143, 137, -15]) PASS: no error found in rc log PASS: no error found in stdout log PASS: no error found in stderr log ________________________________________________________________________________ [2025-03-19 16:12:10] pkce-access-token-10 print_overseer_logs : Print overseer logs from the K8s pod ________________________________________________________________________________ Task result is INIT no need to display logs. ________________________________________________________________________________ [2025-03-19 16:12:11] pkce-access-token-10 post : Post ________________________________________________________________________________ Setting result to PASS Task has been successfully stopped