[2025-02-06T05:35:47.216Z] Running test jdk_net_0 ... [2025-02-06T05:35:47.216Z] =============================================== [2025-02-06T05:35:47.216Z] jdk_net_0 Start Time: Wed Feb 5 21:35:46 2025 Epoch Time (ms): 1738820146319 [2025-02-06T05:35:47.216Z] variation: Mode150 [2025-02-06T05:35:47.216Z] JVM_OPTIONS: -XX:+UseCompressedOops [2025-02-06T05:35:47.216Z] { \ [2025-02-06T05:35:47.216Z] echo ""; echo "TEST SETUP:"; \ [2025-02-06T05:35:47.216Z] echo "Nothing to be done for setup."; \ [2025-02-06T05:35:47.216Z] mkdir -p "/Users/admin/workspace/workspace/Test_openjdk17_hs_extended.openjdk_x86-64_mac_testList_1/aqa-tests/TKG/../TKG/output_17388008003671/jdk_net_0"; \ [2025-02-06T05:35:47.216Z] cd "/Users/admin/workspace/workspace/Test_openjdk17_hs_extended.openjdk_x86-64_mac_testList_1/aqa-tests/TKG/../TKG/output_17388008003671/jdk_net_0"; \ [2025-02-06T05:35:47.216Z] echo ""; echo "TESTING:"; \ [2025-02-06T05:35:47.216Z] "/Users/admin/workspace/workspace/Test_openjdk17_hs_extended.openjdk_x86-64_mac_testList_1/jdkbinary/j2sdk-image/Contents/Home/bin/..//bin/java" -Xmx512m -jar "/Users/admin/workspace/workspace/Test_openjdk17_hs_extended.openjdk_x86-64_mac_testList_1/aqa-tests/TKG/../../jvmtest/openjdk/jtreg/lib/jtreg.jar" \ [2025-02-06T05:35:47.216Z] -agentvm -a -ea -esa -v:fail,error,time,nopass -retain:fail,error,*.dmp,javacore.*,heapdump.*,*.trc -ignore:quiet -timeoutFactor:8 -xml:verify -concurrency:2 -nativepath:"/Users/admin/workspace/workspace/Test_openjdk17_hs_extended.openjdk_x86-64_mac_testList_1/jdkbinary/openjdk-test-image/jdk/jtreg/native" -vmoptions:"-Xmx512m -XX:+UseCompressedOops " \ [2025-02-06T05:35:47.217Z] -w ""/Users/admin/workspace/workspace/Test_openjdk17_hs_extended.openjdk_x86-64_mac_testList_1/aqa-tests/TKG/../TKG/output_17388008003671/jdk_net_0"/work" \ [2025-02-06T05:35:47.217Z] -r ""/Users/admin/workspace/workspace/Test_openjdk17_hs_extended.openjdk_x86-64_mac_testList_1/aqa-tests/TKG/../TKG/output_17388008003671/jdk_net_0"/report" \ [2025-02-06T05:35:47.217Z] -jdk:"/Users/admin/workspace/workspace/Test_openjdk17_hs_extended.openjdk_x86-64_mac_testList_1/jdkbinary/j2sdk-image/Contents/Home/bin/../" \ [2025-02-06T05:35:47.217Z] -exclude:"/Users/admin/workspace/workspace/Test_openjdk17_hs_extended.openjdk_x86-64_mac_testList_1/aqa-tests/TKG/../openjdk/openjdk-jdk/test/jdk/ProblemList.txt" \ [2025-02-06T05:35:47.217Z] -exclude:"/Users/admin/workspace/workspace/Test_openjdk17_hs_extended.openjdk_x86-64_mac_testList_1/aqa-tests/TKG/../../jvmtest/openjdk/excludes/ProblemList_openjdk17.txt" \ [2025-02-06T05:35:47.217Z] \ [2025-02-06T05:35:47.217Z] -exclude:"/Users/admin/workspace/workspace/Test_openjdk17_hs_extended.openjdk_x86-64_mac_testList_1/aqa-tests/TKG/../openjdk/excludes/vendors/eclipse/ProblemList_openjdk17.txt" \ [2025-02-06T05:35:47.217Z] "/Users/admin/workspace/workspace/Test_openjdk17_hs_extended.openjdk_x86-64_mac_testList_1/aqa-tests/TKG/../openjdk/openjdk-jdk/test/jdk:jdk_net"; \ [2025-02-06T05:35:47.217Z] if [ $? -eq 0 ]; then echo "-----------------------------------"; echo "jdk_net_0""_PASSED"; echo "-----------------------------------"; cd /Users/admin/workspace/workspace/Test_openjdk17_hs_extended.openjdk_x86-64_mac_testList_1/aqa-tests/TKG/..; else echo "-----------------------------------"; echo "jdk_net_0""_FAILED"; echo "-----------------------------------"; fi; \ [2025-02-06T05:35:47.217Z] echo ""; echo "TEST TEARDOWN:"; \ [2025-02-06T05:35:47.217Z] echo "Nothing to be done for teardown."; \ [2025-02-06T05:35:47.217Z] } 2>&1 | tee -a "/Users/admin/workspace/workspace/Test_openjdk17_hs_extended.openjdk_x86-64_mac_testList_1/aqa-tests/TKG/../TKG/output_17388008003671/TestTargetResult"; [2025-02-06T05:35:47.600Z] [2025-02-06T05:35:47.600Z] TEST SETUP: [2025-02-06T05:35:47.600Z] Nothing to be done for setup. [2025-02-06T05:35:47.600Z] [2025-02-06T05:35:47.600Z] TESTING: [2025-02-06T05:35:51.668Z] Directory "/Users/admin/workspace/workspace/Test_openjdk17_hs_extended.openjdk_x86-64_mac_testList_1/aqa-tests/TKG/../TKG/output_17388008003671/jdk_net_0/work" not found: creating [2025-02-06T05:35:51.668Z] Directory "/Users/admin/workspace/workspace/Test_openjdk17_hs_extended.openjdk_x86-64_mac_testList_1/aqa-tests/TKG/../TKG/output_17388008003671/jdk_net_0/report" not found: creating [2025-02-06T05:36:10.227Z] XML output with verification to /Users/admin/workspace/workspace/Test_openjdk17_hs_extended.openjdk_x86-64_mac_testList_1/aqa-tests/TKG/output_17388008003671/jdk_net_0/work [2025-02-06T06:04:07.379Z] -------------------------------------------------- [2025-02-06T06:04:07.379Z] TEST: java/net/httpclient/DependentPromiseActionsTest.java [2025-02-06T06:04:07.379Z] TEST JDK: /Users/admin/workspace/workspace/Test_openjdk17_hs_extended.openjdk_x86-64_mac_testList_1/jdkbinary/j2sdk-image/Contents/Home/bin/.. [2025-02-06T06:04:07.379Z] [2025-02-06T06:04:07.379Z] ACTION: build -- Passed. Build successful [2025-02-06T06:04:07.379Z] REASON: User specified action: run build jdk.httpclient.test.lib.common.HttpServerAdapters jdk.test.lib.net.SimpleSSLContext DependentPromiseActionsTest [2025-02-06T06:04:07.379Z] TIME: 1.386 seconds [2025-02-06T06:04:07.379Z] messages: [2025-02-06T06:04:07.379Z] command: build jdk.httpclient.test.lib.common.HttpServerAdapters jdk.test.lib.net.SimpleSSLContext DependentPromiseActionsTest [2025-02-06T06:04:07.379Z] reason: User specified action: run build jdk.httpclient.test.lib.common.HttpServerAdapters jdk.test.lib.net.SimpleSSLContext DependentPromiseActionsTest [2025-02-06T06:04:07.379Z] started: Wed Feb 05 22:03:33 PST 2025 [2025-02-06T06:04:07.379Z] Test directory: [2025-02-06T06:04:07.379Z] compile: DependentPromiseActionsTest [2025-02-06T06:04:07.379Z] finished: Wed Feb 05 22:03:34 PST 2025 [2025-02-06T06:04:07.379Z] elapsed time (seconds): 1.386 [2025-02-06T06:04:07.379Z] [2025-02-06T06:04:07.379Z] ACTION: compile -- Passed. Compilation successful [2025-02-06T06:04:07.379Z] REASON: .class file out of date or does not exist [2025-02-06T06:04:07.379Z] TIME: 1.361 seconds [2025-02-06T06:04:07.379Z] messages: [2025-02-06T06:04:07.379Z] command: compile /Users/admin/workspace/workspace/Test_openjdk17_hs_extended.openjdk_x86-64_mac_testList_1/aqa-tests/openjdk/openjdk-jdk/test/jdk/java/net/httpclient/DependentPromiseActionsTest.java [2025-02-06T06:04:07.379Z] reason: .class file out of date or does not exist [2025-02-06T06:04:07.379Z] started: Wed Feb 05 22:03:33 PST 2025 [2025-02-06T06:04:07.379Z] Additional options from @modules: --add-modules java.base,java.net.http,java.logging,jdk.httpserver --add-exports java.base/sun.net.www.http=ALL-UNNAMED --add-exports java.base/sun.net.www=ALL-UNNAMED --add-exports java.base/sun.net=ALL-UNNAMED --add-exports java.net.http/jdk.internal.net.http.common=ALL-UNNAMED --add-exports java.net.http/jdk.internal.net.http.frame=ALL-UNNAMED --add-exports java.net.http/jdk.internal.net.http.hpack=ALL-UNNAMED [2025-02-06T06:04:07.379Z] Mode: agentvm [2025-02-06T06:04:07.379Z] Agent id: 1 [2025-02-06T06:04:07.379Z] finished: Wed Feb 05 22:03:34 PST 2025 [2025-02-06T06:04:07.379Z] elapsed time (seconds): 1.361 [2025-02-06T06:04:07.379Z] configuration: [2025-02-06T06:04:07.379Z] Boot Layer (javac runtime environment) [2025-02-06T06:04:07.379Z] class path: /Users/admin/workspace/workspace/Test_openjdk17_hs_extended.openjdk_x86-64_mac_testList_1/jvmtest/openjdk/jtreg/lib/javatest.jar [2025-02-06T06:04:07.379Z] /Users/admin/workspace/workspace/Test_openjdk17_hs_extended.openjdk_x86-64_mac_testList_1/jvmtest/openjdk/jtreg/lib/jtreg.jar [2025-02-06T06:04:07.379Z] patch: java.base /Users/admin/workspace/workspace/Test_openjdk17_hs_extended.openjdk_x86-64_mac_testList_1/aqa-tests/TKG/output_17388008003671/jdk_net_0/work/patches/java.base [2025-02-06T06:04:07.379Z] [2025-02-06T06:04:07.379Z] javac compilation environment [2025-02-06T06:04:07.379Z] add modules: java.base java.net.http java.logging jdk.httpserver [2025-02-06T06:04:07.379Z] add exports: java.base/sun.net ALL-UNNAMED [2025-02-06T06:04:07.379Z] java.base/sun.net.www ALL-UNNAMED [2025-02-06T06:04:07.379Z] java.base/sun.net.www.http ALL-UNNAMED [2025-02-06T06:04:07.379Z] java.net.http/jdk.internal.net.http.common ALL-UNNAMED [2025-02-06T06:04:07.379Z] java.net.http/jdk.internal.net.http.frame ALL-UNNAMED [2025-02-06T06:04:07.379Z] java.net.http/jdk.internal.net.http.hpack ALL-UNNAMED [2025-02-06T06:04:07.379Z] source path: /Users/admin/workspace/workspace/Test_openjdk17_hs_extended.openjdk_x86-64_mac_testList_1/aqa-tests/openjdk/openjdk-jdk/test/jdk/java/net/httpclient [2025-02-06T06:04:07.379Z] /Users/admin/workspace/workspace/Test_openjdk17_hs_extended.openjdk_x86-64_mac_testList_1/aqa-tests/openjdk/openjdk-jdk/test/lib [2025-02-06T06:04:07.379Z] /Users/admin/workspace/workspace/Test_openjdk17_hs_extended.openjdk_x86-64_mac_testList_1/aqa-tests/openjdk/openjdk-jdk/test/jdk/java/net/httpclient/lib [2025-02-06T06:04:07.380Z] class path: /Users/admin/workspace/workspace/Test_openjdk17_hs_extended.openjdk_x86-64_mac_testList_1/aqa-tests/openjdk/openjdk-jdk/test/jdk/java/net/httpclient [2025-02-06T06:04:07.380Z] /Users/admin/workspace/workspace/Test_openjdk17_hs_extended.openjdk_x86-64_mac_testList_1/aqa-tests/TKG/output_17388008003671/jdk_net_0/work/classes/0/java/net/httpclient/DependentPromiseActionsTest.d [2025-02-06T06:04:07.380Z] /Users/admin/workspace/workspace/Test_openjdk17_hs_extended.openjdk_x86-64_mac_testList_1/aqa-tests/TKG/output_17388008003671/jdk_net_0/work/classes/0/test/lib [2025-02-06T06:04:07.380Z] /Users/admin/workspace/workspace/Test_openjdk17_hs_extended.openjdk_x86-64_mac_testList_1/aqa-tests/TKG/output_17388008003671/jdk_net_0/work/classes/0/test/jdk/java/net/httpclient/lib [2025-02-06T06:04:07.380Z] /Users/admin/workspace/workspace/Test_openjdk17_hs_extended.openjdk_x86-64_mac_testList_1/jvmtest/openjdk/jtreg/lib/testng-7.3.0.jar [2025-02-06T06:04:07.380Z] /Users/admin/workspace/workspace/Test_openjdk17_hs_extended.openjdk_x86-64_mac_testList_1/jvmtest/openjdk/jtreg/lib/guice-5.1.0.jar [2025-02-06T06:04:07.380Z] /Users/admin/workspace/workspace/Test_openjdk17_hs_extended.openjdk_x86-64_mac_testList_1/jvmtest/openjdk/jtreg/lib/jcommander-1.82.jar [2025-02-06T06:04:07.380Z] [2025-02-06T06:04:07.380Z] rerun: [2025-02-06T06:04:07.380Z] cd /Users/admin/workspace/workspace/Test_openjdk17_hs_extended.openjdk_x86-64_mac_testList_1/aqa-tests/TKG/output_17388008003671/jdk_net_0/work/scratch/1 && \ [2025-02-06T06:04:07.380Z] HOME=/Users/admin \ [2025-02-06T06:04:07.380Z] PATH=/bin:/usr/bin:/usr/sbin \ [2025-02-06T06:04:07.380Z] /Users/admin/workspace/workspace/Test_openjdk17_hs_extended.openjdk_x86-64_mac_testList_1/jdkbinary/j2sdk-image/Contents/Home/bin/../bin/javac \ [2025-02-06T06:04:07.380Z] -J-ea \ [2025-02-06T06:04:07.380Z] -J-esa \ [2025-02-06T06:04:07.380Z] -J-Xmx512m \ [2025-02-06T06:04:07.380Z] -J-XX:+UseCompressedOops \ [2025-02-06T06:04:07.380Z] -J-Dtest.vm.opts='-ea -esa -Xmx512m -XX:+UseCompressedOops' \ [2025-02-06T06:04:07.380Z] -J-Dtest.tool.vm.opts='-J-ea -J-esa -J-Xmx512m -J-XX:+UseCompressedOops' \ [2025-02-06T06:04:07.380Z] -J-Dtest.compiler.opts= \ [2025-02-06T06:04:07.380Z] -J-Dtest.java.opts= \ [2025-02-06T06:04:07.380Z] -J-Dtest.jdk=/Users/admin/workspace/workspace/Test_openjdk17_hs_extended.openjdk_x86-64_mac_testList_1/jdkbinary/j2sdk-image/Contents/Home/bin/.. \ [2025-02-06T06:04:07.380Z] -J-Dcompile.jdk=/Users/admin/workspace/workspace/Test_openjdk17_hs_extended.openjdk_x86-64_mac_testList_1/jdkbinary/j2sdk-image/Contents/Home/bin/.. \ [2025-02-06T06:04:07.380Z] -J-Dtest.timeout.factor=8.0 \ [2025-02-06T06:04:07.380Z] -J-Dtest.nativepath=/Users/admin/workspace/workspace/Test_openjdk17_hs_extended.openjdk_x86-64_mac_testList_1/jdkbinary/openjdk-test-image/jdk/jtreg/native \ [2025-02-06T06:04:07.380Z] -J-Dtest.root=/Users/admin/workspace/workspace/Test_openjdk17_hs_extended.openjdk_x86-64_mac_testList_1/aqa-tests/openjdk/openjdk-jdk/test/jdk \ [2025-02-06T06:04:07.380Z] -J-Dtest.name=java/net/httpclient/DependentPromiseActionsTest.java \ [2025-02-06T06:04:07.380Z] -J-Dtest.file=/Users/admin/workspace/workspace/Test_openjdk17_hs_extended.openjdk_x86-64_mac_testList_1/aqa-tests/openjdk/openjdk-jdk/test/jdk/java/net/httpclient/DependentPromiseActionsTest.java \ [2025-02-06T06:04:07.380Z] -J-Dtest.src=/Users/admin/workspace/workspace/Test_openjdk17_hs_extended.openjdk_x86-64_mac_testList_1/aqa-tests/openjdk/openjdk-jdk/test/jdk/java/net/httpclient \ [2025-02-06T06:04:07.380Z] -J-Dtest.src.path=/Users/admin/workspace/workspace/Test_openjdk17_hs_extended.openjdk_x86-64_mac_testList_1/aqa-tests/openjdk/openjdk-jdk/test/jdk/java/net/httpclient:/Users/admin/workspace/workspace/Test_openjdk17_hs_extended.openjdk_x86-64_mac_testList_1/aqa-tests/openjdk/openjdk-jdk/test/lib:/Users/admin/workspace/workspace/Test_openjdk17_hs_extended.openjdk_x86-64_mac_testList_1/aqa-tests/openjdk/openjdk-jdk/test/jdk/java/net/httpclient/lib \ [2025-02-06T06:04:07.380Z] -J-Dtest.classes=/Users/admin/workspace/workspace/Test_openjdk17_hs_extended.openjdk_x86-64_mac_testList_1/aqa-tests/TKG/output_17388008003671/jdk_net_0/work/classes/0/java/net/httpclient/DependentPromiseActionsTest.d \ [2025-02-06T06:04:07.380Z] -J-Dtest.class.path=/Users/admin/workspace/workspace/Test_openjdk17_hs_extended.openjdk_x86-64_mac_testList_1/aqa-tests/TKG/output_17388008003671/jdk_net_0/work/classes/0/java/net/httpclient/DependentPromiseActionsTest.d:/Users/admin/workspace/workspace/Test_openjdk17_hs_extended.openjdk_x86-64_mac_testList_1/aqa-tests/TKG/output_17388008003671/jdk_net_0/work/classes/0/test/lib:/Users/admin/workspace/workspace/Test_openjdk17_hs_extended.openjdk_x86-64_mac_testList_1/aqa-tests/TKG/output_17388008003671/jdk_net_0/work/classes/0/test/jdk/java/net/httpclient/lib \ [2025-02-06T06:04:07.380Z] -J-Dtest.class.path.prefix=/Users/admin/workspace/workspace/Test_openjdk17_hs_extended.openjdk_x86-64_mac_testList_1/aqa-tests/TKG/output_17388008003671/jdk_net_0/work/classes/0/java/net/httpclient/DependentPromiseActionsTest.d:/Users/admin/workspace/workspace/Test_openjdk17_hs_extended.openjdk_x86-64_mac_testList_1/aqa-tests/openjdk/openjdk-jdk/test/jdk/java/net/httpclient:/Users/admin/workspace/workspace/Test_openjdk17_hs_extended.openjdk_x86-64_mac_testList_1/aqa-tests/TKG/output_17388008003671/jdk_net_0/work/classes/0/test/lib:/Users/admin/workspace/workspace/Test_openjdk17_hs_extended.openjdk_x86-64_mac_testList_1/aqa-tests/TKG/output_17388008003671/jdk_net_0/work/classes/0/test/jdk/java/net/httpclient/lib \ [2025-02-06T06:04:07.380Z] -J-Dtest.modules='java.base/sun.net.www.http java.base/sun.net.www java.base/sun.net java.net.http/jdk.internal.net.http.common java.net.http/jdk.internal.net.http.frame java.net.http/jdk.internal.net.http.hpack java.logging jdk.httpserver' \ [2025-02-06T06:04:07.380Z] --add-modules java.base,java.net.http,java.logging,jdk.httpserver \ [2025-02-06T06:04:07.380Z] --add-exports java.base/sun.net.www.http=ALL-UNNAMED \ [2025-02-06T06:04:07.380Z] --add-exports java.base/sun.net.www=ALL-UNNAMED \ [2025-02-06T06:04:07.380Z] --add-exports java.base/sun.net=ALL-UNNAMED \ [2025-02-06T06:04:07.380Z] --add-exports java.net.http/jdk.internal.net.http.common=ALL-UNNAMED \ [2025-02-06T06:04:07.380Z] --add-exports java.net.http/jdk.internal.net.http.frame=ALL-UNNAMED \ [2025-02-06T06:04:07.380Z] --add-exports java.net.http/jdk.internal.net.http.hpack=ALL-UNNAMED \ [2025-02-06T06:04:07.380Z] -d /Users/admin/workspace/workspace/Test_openjdk17_hs_extended.openjdk_x86-64_mac_testList_1/aqa-tests/TKG/output_17388008003671/jdk_net_0/work/classes/0/java/net/httpclient/DependentPromiseActionsTest.d \ [2025-02-06T06:04:07.380Z] -sourcepath /Users/admin/workspace/workspace/Test_openjdk17_hs_extended.openjdk_x86-64_mac_testList_1/aqa-tests/openjdk/openjdk-jdk/test/jdk/java/net/httpclient:/Users/admin/workspace/workspace/Test_openjdk17_hs_extended.openjdk_x86-64_mac_testList_1/aqa-tests/openjdk/openjdk-jdk/test/lib:/Users/admin/workspace/workspace/Test_openjdk17_hs_extended.openjdk_x86-64_mac_testList_1/aqa-tests/openjdk/openjdk-jdk/test/jdk/java/net/httpclient/lib \ [2025-02-06T06:04:07.380Z] -classpath /Users/admin/workspace/workspace/Test_openjdk17_hs_extended.openjdk_x86-64_mac_testList_1/aqa-tests/openjdk/openjdk-jdk/test/jdk/java/net/httpclient:/Users/admin/workspace/workspace/Test_openjdk17_hs_extended.openjdk_x86-64_mac_testList_1/aqa-tests/TKG/output_17388008003671/jdk_net_0/work/classes/0/java/net/httpclient/DependentPromiseActionsTest.d:/Users/admin/workspace/workspace/Test_openjdk17_hs_extended.openjdk_x86-64_mac_testList_1/aqa-tests/TKG/output_17388008003671/jdk_net_0/work/classes/0/test/lib:/Users/admin/workspace/workspace/Test_openjdk17_hs_extended.openjdk_x86-64_mac_testList_1/aqa-tests/TKG/output_17388008003671/jdk_net_0/work/classes/0/test/jdk/java/net/httpclient/lib:/Users/admin/workspace/workspace/Test_openjdk17_hs_extended.openjdk_x86-64_mac_testList_1/jvmtest/openjdk/jtreg/lib/testng-7.3.0.jar:/Users/admin/workspace/workspace/Test_openjdk17_hs_extended.openjdk_x86-64_mac_testList_1/jvmtest/openjdk/jtreg/lib/guice-5.1.0.jar:/Users/admin/workspace/workspace/Test_openjdk17_hs_extended.openjdk_x86-64_mac_testList_1/jvmtest/openjdk/jtreg/lib/jcommander-1.82.jar /Users/admin/workspace/workspace/Test_openjdk17_hs_extended.openjdk_x86-64_mac_testList_1/aqa-tests/openjdk/openjdk-jdk/test/jdk/java/net/httpclient/DependentPromiseActionsTest.java [2025-02-06T06:04:07.380Z] direct: [2025-02-06T06:04:07.380Z] /Users/admin/workspace/workspace/Test_openjdk17_hs_extended.openjdk_x86-64_mac_testList_1/aqa-tests/openjdk/openjdk-jdk/test/jdk/java/net/httpclient/DependentPromiseActionsTest.java:489: warning: [removal] getSecurityManager() in System has been deprecated and marked for removal [2025-02-06T06:04:07.380Z] } else if (System.getSecurityManager() != null) { [2025-02-06T06:04:07.380Z] ^ [2025-02-06T06:04:07.380Z] Note: /Users/admin/workspace/workspace/Test_openjdk17_hs_extended.openjdk_x86-64_mac_testList_1/aqa-tests/openjdk/openjdk-jdk/test/jdk/java/net/httpclient/DependentPromiseActionsTest.java uses unchecked or unsafe operations. [2025-02-06T06:04:07.380Z] Note: Recompile with -Xlint:unchecked for details. [2025-02-06T06:04:07.380Z] 1 warning [2025-02-06T06:04:07.380Z] [2025-02-06T06:04:07.380Z] ACTION: build -- Passed. All files up to date [2025-02-06T06:04:07.380Z] REASON: Named class compiled on demand [2025-02-06T06:04:07.380Z] TIME: 0.001 seconds [2025-02-06T06:04:07.380Z] messages: [2025-02-06T06:04:07.380Z] command: build DependentPromiseActionsTest [2025-02-06T06:04:07.380Z] reason: Named class compiled on demand [2025-02-06T06:04:07.380Z] started: Wed Feb 05 22:03:34 PST 2025 [2025-02-06T06:04:07.380Z] finished: Wed Feb 05 22:03:34 PST 2025 [2025-02-06T06:04:07.380Z] elapsed time (seconds): 0.001 [2025-02-06T06:04:07.380Z] [2025-02-06T06:04:07.380Z] ACTION: testng -- Failed. Execution failed: `main' threw exception: java.lang.Exception: failures: 1 [2025-02-06T06:04:07.380Z] REASON: User specified action: run testng/othervm -Djdk.internal.httpclient.debug=true DependentPromiseActionsTest [2025-02-06T06:04:07.380Z] TIME: 21.879 seconds [2025-02-06T06:04:07.380Z] messages: [2025-02-06T06:04:07.380Z] command: testng -Djdk.internal.httpclient.debug=true DependentPromiseActionsTest [2025-02-06T06:04:07.380Z] reason: User specified action: run testng/othervm -Djdk.internal.httpclient.debug=true DependentPromiseActionsTest [2025-02-06T06:04:07.380Z] started: Wed Feb 05 22:03:34 PST 2025 [2025-02-06T06:04:07.380Z] Mode: othervm [/othervm specified] [2025-02-06T06:04:07.380Z] Additional options from @modules: --add-modules java.base,java.net.http,java.logging,jdk.httpserver --add-exports java.base/sun.net.www.http=ALL-UNNAMED --add-exports java.base/sun.net.www=ALL-UNNAMED --add-exports java.base/sun.net=ALL-UNNAMED --add-exports java.net.http/jdk.internal.net.http.common=ALL-UNNAMED --add-exports java.net.http/jdk.internal.net.http.frame=ALL-UNNAMED --add-exports java.net.http/jdk.internal.net.http.hpack=ALL-UNNAMED [2025-02-06T06:04:07.380Z] finished: Wed Feb 05 22:03:56 PST 2025 [2025-02-06T06:04:07.380Z] elapsed time (seconds): 21.879 [2025-02-06T06:04:07.380Z] configuration: [2025-02-06T06:04:07.380Z] Boot Layer [2025-02-06T06:04:07.380Z] add modules: java.base java.net.http java.logging jdk.httpserver [2025-02-06T06:04:07.380Z] add exports: java.base/sun.net ALL-UNNAMED [2025-02-06T06:04:07.380Z] java.base/sun.net.www ALL-UNNAMED [2025-02-06T06:04:07.380Z] java.base/sun.net.www.http ALL-UNNAMED [2025-02-06T06:04:07.380Z] java.net.http/jdk.internal.net.http.common ALL-UNNAMED [2025-02-06T06:04:07.380Z] java.net.http/jdk.internal.net.http.frame ALL-UNNAMED [2025-02-06T06:04:07.380Z] java.net.http/jdk.internal.net.http.hpack ALL-UNNAMED [2025-02-06T06:04:07.380Z] [2025-02-06T06:04:07.380Z] STDOUT: [2025-02-06T06:04:07.380Z] Http2TestServerImpl[localhost/127.0.0.1:54981]::addHandler DependentPromiseActionsTest$HTTP_FixedLengthHandler@1a13b4db, /http2/fixed [2025-02-06T06:04:07.380Z] Http2TestServerImpl[localhost/127.0.0.1:54981]::addHandler DependentPromiseActionsTest$HTTP_ChunkedHandler@796a1c31, /http2/chunk [2025-02-06T06:04:07.380Z] Http2TestServerImpl[localhost/127.0.0.1:54983]::addHandler DependentPromiseActionsTest$HTTP_FixedLengthHandler@1a13b4db, /https2/fixed [2025-02-06T06:04:07.380Z] Http2TestServerImpl[localhost/127.0.0.1:54983]::addHandler DependentPromiseActionsTest$HTTP_ChunkedHandler@796a1c31, /https2/chunk [2025-02-06T06:04:07.380Z] Http2TestServerImpl: start [2025-02-06T06:04:07.380Z] Http2TestServerImpl: start [2025-02-06T06:04:07.380Z] config DependentPromiseActionsTest.setup(): success [2025-02-06T06:04:07.380Z] [2025-02-06T06:04:07.380Z] [2 s, 625 ms, 648695 ns] testAsInputStreamAsync(http://127.0.0.1:54981/http2/fixed/y, false, SemaphoreStaller) [2025-02-06T06:04:07.380Z] try stalling in BODY_HANDLER [2025-02-06T06:04:07.380Z] Http2TestContext::handle Http2TestExchangeImpl: jdk.httpclient.test.lib.http2.Http2TestExchangeImpl@5a2f4d47 [2025-02-06T06:04:07.380Z] HTTP_FixedLengthHandler received request to http://127.0.0.1:54981/http2/fixed/y [2025-02-06T06:04:07.380Z] TestServer: [5 s, 760 ms, 155291 ns] Pushing promise: http://127.0.0.1:54981/http2/fixed/y/before/promise-1 [2025-02-06T06:04:07.380Z] TestServer: [5 s, 816 ms, 72344 ns] Pushing promise: http://127.0.0.1:54981/http2/fixed/y/after/promise-2 [2025-02-06T06:04:07.380Z] TestServer: [5 s, 821 ms, 298871 ns] Pushing promise: http://127.0.0.1:54981/http2/fixed/y/after/promise-3 [2025-02-06T06:04:07.380Z] test DependentPromiseActionsTest.testAsInputStreamAsync("http://127.0.0.1:54981/http2/fixed/y", false, SemaphoreStaller): success [2025-02-06T06:04:07.380Z] [2025-02-06T06:04:07.380Z] [7 s, 290 ms, 677368 ns] testAsInputStreamAsync(http://127.0.0.1:54981/http2/chunk/y, false, SemaphoreStaller) [2025-02-06T06:04:07.380Z] try stalling in BODY_HANDLER [2025-02-06T06:04:07.380Z] Http2TestContext::handle Http2TestExchangeImpl: jdk.httpclient.test.lib.http2.Http2TestExchangeImpl@63009025 [2025-02-06T06:04:07.380Z] HTTP_ChunkedHandler received request to http://127.0.0.1:54981/http2/chunk/y [2025-02-06T06:04:07.380Z] TestServer: [7 s, 587 ms, 689718 ns] Pushing promise: http://127.0.0.1:54981/http2/chunk/y/before/promise-1 [2025-02-06T06:04:07.380Z] TestServer: [7 s, 589 ms, 438761 ns] Pushing promise: http://127.0.0.1:54981/http2/chunk/y/after/promise-2 [2025-02-06T06:04:07.380Z] TestServer: [7 s, 617 ms, 595998 ns] Pushing promise: http://127.0.0.1:54981/http2/chunk/y/after/promise-3 [2025-02-06T06:04:07.380Z] test DependentPromiseActionsTest.testAsInputStreamAsync("http://127.0.0.1:54981/http2/chunk/y", false, SemaphoreStaller): success [2025-02-06T06:04:07.380Z] [2025-02-06T06:04:07.380Z] [7 s, 919 ms, 464851 ns] testAsInputStreamAsync(https://127.0.0.1:54983/https2/fixed/y, false, SemaphoreStaller) [2025-02-06T06:04:07.380Z] try stalling in BODY_HANDLER [2025-02-06T06:04:07.380Z] Http2TestContext::handle Http2TestExchangeImpl: jdk.httpclient.test.lib.http2.Http2TestExchangeImpl@6f271202 [2025-02-06T06:04:07.380Z] HTTP_FixedLengthHandler received request to https://127.0.0.1:54983/https2/fixed/y [2025-02-06T06:04:07.380Z] TestServer: [16 s, 985 ms, 603899 ns] Pushing promise: https://127.0.0.1:54983/https2/fixed/y/before/promise-1 [2025-02-06T06:04:07.380Z] TestServer: [16 s, 986 ms, 40687 ns] Pushing promise: https://127.0.0.1:54983/https2/fixed/y/after/promise-2 [2025-02-06T06:04:07.380Z] TestServer: [16 s, 986 ms, 283726 ns] Pushing promise: https://127.0.0.1:54983/https2/fixed/y/after/promise-3 [2025-02-06T06:04:07.380Z] test DependentPromiseActionsTest.testAsInputStreamAsync("https://127.0.0.1:54983/https2/fixed/y", false, SemaphoreStaller): success [2025-02-06T06:04:07.380Z] [2025-02-06T06:04:07.380Z] [17 s, 69 ms, 277014 ns] testAsInputStreamAsync(https://127.0.0.1:54983/https2/chunk/y, false, SemaphoreStaller) [2025-02-06T06:04:07.380Z] try stalling in BODY_HANDLER [2025-02-06T06:04:07.380Z] Http2TestContext::handle Http2TestExchangeImpl: jdk.httpclient.test.lib.http2.Http2TestExchangeImpl@6c829353 [2025-02-06T06:04:07.380Z] HTTP_ChunkedHandler received request to https://127.0.0.1:54983/https2/chunk/y [2025-02-06T06:04:07.380Z] TestServer: [17 s, 244 ms, 13646 ns] Pushing promise: https://127.0.0.1:54983/https2/chunk/y/before/promise-1 [2025-02-06T06:04:07.380Z] TestServer: [17 s, 244 ms, 215711 ns] Pushing promise: https://127.0.0.1:54983/https2/chunk/y/after/promise-2 [2025-02-06T06:04:07.380Z] TestServer: [17 s, 244 ms, 362946 ns] Pushing promise: https://127.0.0.1:54983/https2/chunk/y/after/promise-3 [2025-02-06T06:04:07.380Z] test DependentPromiseActionsTest.testAsInputStreamAsync("https://127.0.0.1:54983/https2/chunk/y", false, SemaphoreStaller): success [2025-02-06T06:04:07.380Z] [2025-02-06T06:04:07.380Z] [17 s, 298 ms, 139463 ns] testAsInputStreamAsync(http://127.0.0.1:54981/http2/fixed/y, true, SemaphoreStaller) [2025-02-06T06:04:07.380Z] try stalling in BODY_HANDLER [2025-02-06T06:04:07.380Z] Http2TestContext::handle Http2TestExchangeImpl: jdk.httpclient.test.lib.http2.Http2TestExchangeImpl@6dc76235 [2025-02-06T06:04:07.380Z] HTTP_FixedLengthHandler received request to http://127.0.0.1:54981/http2/fixed/y [2025-02-06T06:04:07.380Z] TestServer: [17 s, 341 ms, 270143 ns] Pushing promise: http://127.0.0.1:54981/http2/fixed/y/before/promise-1 [2025-02-06T06:04:07.380Z] TestServer: [17 s, 341 ms, 477726 ns] Pushing promise: http://127.0.0.1:54981/http2/fixed/y/after/promise-2 [2025-02-06T06:04:07.380Z] TestServer: [17 s, 341 ms, 641107 ns] Pushing promise: http://127.0.0.1:54981/http2/fixed/y/after/promise-3 [2025-02-06T06:04:07.380Z] test DependentPromiseActionsTest.testAsInputStreamAsync("http://127.0.0.1:54981/http2/fixed/y", true, SemaphoreStaller): success [2025-02-06T06:04:07.380Z] [2025-02-06T06:04:07.380Z] [17 s, 386 ms, 212153 ns] testAsInputStreamAsync(http://127.0.0.1:54981/http2/chunk/y, true, SemaphoreStaller) [2025-02-06T06:04:07.380Z] try stalling in BODY_HANDLER [2025-02-06T06:04:07.380Z] Http2TestContext::handle Http2TestExchangeImpl: jdk.httpclient.test.lib.http2.Http2TestExchangeImpl@65964cae [2025-02-06T06:04:07.380Z] HTTP_ChunkedHandler received request to http://127.0.0.1:54981/http2/chunk/y [2025-02-06T06:04:07.380Z] TestServer: [17 s, 387 ms, 724598 ns] Pushing promise: http://127.0.0.1:54981/http2/chunk/y/before/promise-1 [2025-02-06T06:04:07.380Z] TestServer: [17 s, 387 ms, 925385 ns] Pushing promise: http://127.0.0.1:54981/http2/chunk/y/after/promise-2 [2025-02-06T06:04:07.380Z] TestServer: [17 s, 388 ms, 72231 ns] Pushing promise: http://127.0.0.1:54981/http2/chunk/y/after/promise-3 [2025-02-06T06:04:07.380Z] test DependentPromiseActionsTest.testAsInputStreamAsync("http://127.0.0.1:54981/http2/chunk/y", true, SemaphoreStaller): success [2025-02-06T06:04:07.380Z] [2025-02-06T06:04:07.380Z] [17 s, 410 ms, 90728 ns] testAsInputStreamAsync(https://127.0.0.1:54983/https2/fixed/y, true, SemaphoreStaller) [2025-02-06T06:04:07.380Z] try stalling in BODY_HANDLER [2025-02-06T06:04:07.380Z] Http2TestContext::handle Http2TestExchangeImpl: jdk.httpclient.test.lib.http2.Http2TestExchangeImpl@6b189b3e [2025-02-06T06:04:07.380Z] HTTP_FixedLengthHandler received request to https://127.0.0.1:54983/https2/fixed/y [2025-02-06T06:04:07.380Z] TestServer: [17 s, 480 ms, 394658 ns] Pushing promise: https://127.0.0.1:54983/https2/fixed/y/before/promise-1 [2025-02-06T06:04:07.380Z] TestServer: [17 s, 480 ms, 671589 ns] Pushing promise: https://127.0.0.1:54983/https2/fixed/y/after/promise-2 [2025-02-06T06:04:07.380Z] TestServer: [17 s, 480 ms, 847156 ns] Pushing promise: https://127.0.0.1:54983/https2/fixed/y/after/promise-3 [2025-02-06T06:04:07.380Z] test DependentPromiseActionsTest.testAsInputStreamAsync("https://127.0.0.1:54983/https2/fixed/y", true, SemaphoreStaller): success [2025-02-06T06:04:07.380Z] [2025-02-06T06:04:07.380Z] [17 s, 593 ms, 427842 ns] testAsInputStreamAsync(https://127.0.0.1:54983/https2/chunk/y, true, SemaphoreStaller) [2025-02-06T06:04:07.380Z] try stalling in BODY_HANDLER [2025-02-06T06:04:07.380Z] Http2TestContext::handle Http2TestExchangeImpl: jdk.httpclient.test.lib.http2.Http2TestExchangeImpl@42b68950 [2025-02-06T06:04:07.380Z] HTTP_ChunkedHandler received request to https://127.0.0.1:54983/https2/chunk/y [2025-02-06T06:04:07.380Z] TestServer: [17 s, 598 ms, 522312 ns] Pushing promise: https://127.0.0.1:54983/https2/chunk/y/before/promise-1 [2025-02-06T06:04:07.380Z] TestServer: [17 s, 598 ms, 745249 ns] Pushing promise: https://127.0.0.1:54983/https2/chunk/y/after/promise-2 [2025-02-06T06:04:07.380Z] TestServer: [17 s, 598 ms, 905599 ns] Pushing promise: https://127.0.0.1:54983/https2/chunk/y/after/promise-3 [2025-02-06T06:04:07.380Z] test DependentPromiseActionsTest.testAsInputStreamAsync("https://127.0.0.1:54983/https2/chunk/y", true, SemaphoreStaller): success [2025-02-06T06:04:07.380Z] [2025-02-06T06:04:07.380Z] [17 s, 669 ms, 670491 ns] testAsLinesAsync(http://127.0.0.1:54981/http2/fixed/y, false, SemaphoreStaller) [2025-02-06T06:04:07.380Z] try stalling in BODY_HANDLER [2025-02-06T06:04:07.381Z] Http2TestContext::handle Http2TestExchangeImpl: jdk.httpclient.test.lib.http2.Http2TestExchangeImpl@50e22296 [2025-02-06T06:04:07.381Z] HTTP_FixedLengthHandler received request to http://127.0.0.1:54981/http2/fixed/y [2025-02-06T06:04:07.381Z] TestServer: [17 s, 695 ms, 840004 ns] Pushing promise: http://127.0.0.1:54981/http2/fixed/y/before/promise-1 [2025-02-06T06:04:07.381Z] TestServer: [17 s, 696 ms, 39676 ns] Pushing promise: http://127.0.0.1:54981/http2/fixed/y/after/promise-2 [2025-02-06T06:04:07.381Z] TestServer: [17 s, 696 ms, 191189 ns] Pushing promise: http://127.0.0.1:54981/http2/fixed/y/after/promise-3 [2025-02-06T06:04:07.381Z] test DependentPromiseActionsTest.testAsLinesAsync("http://127.0.0.1:54981/http2/fixed/y", false, SemaphoreStaller): success [2025-02-06T06:04:07.381Z] [2025-02-06T06:04:07.381Z] [17 s, 712 ms, 694474 ns] testAsLinesAsync(http://127.0.0.1:54981/http2/chunk/y, false, SemaphoreStaller) [2025-02-06T06:04:07.381Z] try stalling in BODY_HANDLER [2025-02-06T06:04:07.381Z] Http2TestContext::handle Http2TestExchangeImpl: jdk.httpclient.test.lib.http2.Http2TestExchangeImpl@5e25d6fa [2025-02-06T06:04:07.381Z] HTTP_ChunkedHandler received request to http://127.0.0.1:54981/http2/chunk/y [2025-02-06T06:04:07.381Z] TestServer: [17 s, 724 ms, 65572 ns] Pushing promise: http://127.0.0.1:54981/http2/chunk/y/before/promise-1 [2025-02-06T06:04:07.381Z] TestServer: [17 s, 724 ms, 222310 ns] Pushing promise: http://127.0.0.1:54981/http2/chunk/y/after/promise-2 [2025-02-06T06:04:07.381Z] TestServer: [17 s, 724 ms, 348781 ns] Pushing promise: http://127.0.0.1:54981/http2/chunk/y/after/promise-3 [2025-02-06T06:04:07.381Z] test DependentPromiseActionsTest.testAsLinesAsync("http://127.0.0.1:54981/http2/chunk/y", false, SemaphoreStaller): success [2025-02-06T06:04:07.381Z] [2025-02-06T06:04:07.381Z] [17 s, 760 ms, 128005 ns] testAsLinesAsync(https://127.0.0.1:54983/https2/fixed/y, false, SemaphoreStaller) [2025-02-06T06:04:07.381Z] try stalling in BODY_HANDLER [2025-02-06T06:04:07.381Z] Http2TestContext::handle Http2TestExchangeImpl: jdk.httpclient.test.lib.http2.Http2TestExchangeImpl@624570b3 [2025-02-06T06:04:07.381Z] HTTP_FixedLengthHandler received request to https://127.0.0.1:54983/https2/fixed/y [2025-02-06T06:04:07.381Z] TestServer: [17 s, 868 ms, 501169 ns] Pushing promise: https://127.0.0.1:54983/https2/fixed/y/before/promise-1 [2025-02-06T06:04:07.381Z] TestServer: [17 s, 868 ms, 714667 ns] Pushing promise: https://127.0.0.1:54983/https2/fixed/y/after/promise-2 [2025-02-06T06:04:07.381Z] TestServer: [17 s, 868 ms, 851642 ns] Pushing promise: https://127.0.0.1:54983/https2/fixed/y/after/promise-3 [2025-02-06T06:04:07.381Z] test DependentPromiseActionsTest.testAsLinesAsync("https://127.0.0.1:54983/https2/fixed/y", false, SemaphoreStaller): success [2025-02-06T06:04:07.381Z] [2025-02-06T06:04:07.381Z] [17 s, 915 ms, 536546 ns] testAsLinesAsync(https://127.0.0.1:54983/https2/chunk/y, false, SemaphoreStaller) [2025-02-06T06:04:07.381Z] try stalling in BODY_HANDLER [2025-02-06T06:04:07.381Z] Http2TestContext::handle Http2TestExchangeImpl: jdk.httpclient.test.lib.http2.Http2TestExchangeImpl@4c717f76 [2025-02-06T06:04:07.381Z] HTTP_ChunkedHandler received request to https://127.0.0.1:54983/https2/chunk/y [2025-02-06T06:04:07.381Z] TestServer: [18 s, 54 ms, 305448 ns] Pushing promise: https://127.0.0.1:54983/https2/chunk/y/before/promise-1 [2025-02-06T06:04:07.381Z] TestServer: [18 s, 54 ms, 500443 ns] Pushing promise: https://127.0.0.1:54983/https2/chunk/y/after/promise-2 [2025-02-06T06:04:07.381Z] TestServer: [18 s, 54 ms, 646090 ns] Pushing promise: https://127.0.0.1:54983/https2/chunk/y/after/promise-3 [2025-02-06T06:04:07.381Z] test DependentPromiseActionsTest.testAsLinesAsync("https://127.0.0.1:54983/https2/chunk/y", false, SemaphoreStaller): success [2025-02-06T06:04:07.381Z] [2025-02-06T06:04:07.381Z] [18 s, 100 ms, 61699 ns] testAsLinesAsync(http://127.0.0.1:54981/http2/fixed/y, true, SemaphoreStaller) [2025-02-06T06:04:07.381Z] try stalling in BODY_HANDLER [2025-02-06T06:04:07.381Z] Http2TestContext::handle Http2TestExchangeImpl: jdk.httpclient.test.lib.http2.Http2TestExchangeImpl@7e83ea16 [2025-02-06T06:04:07.381Z] HTTP_FixedLengthHandler received request to http://127.0.0.1:54981/http2/fixed/y [2025-02-06T06:04:07.381Z] TestServer: [18 s, 101 ms, 623763 ns] Pushing promise: http://127.0.0.1:54981/http2/fixed/y/before/promise-1 [2025-02-06T06:04:07.381Z] TestServer: [18 s, 101 ms, 807201 ns] Pushing promise: http://127.0.0.1:54981/http2/fixed/y/after/promise-2 [2025-02-06T06:04:07.381Z] TestServer: [18 s, 101 ms, 933810 ns] Pushing promise: http://127.0.0.1:54981/http2/fixed/y/after/promise-3 [2025-02-06T06:04:07.381Z] test DependentPromiseActionsTest.testAsLinesAsync("http://127.0.0.1:54981/http2/fixed/y", true, SemaphoreStaller): success [2025-02-06T06:04:07.381Z] [2025-02-06T06:04:07.381Z] [18 s, 113 ms, 887603 ns] testAsLinesAsync(http://127.0.0.1:54981/http2/chunk/y, true, SemaphoreStaller) [2025-02-06T06:04:07.381Z] try stalling in BODY_HANDLER [2025-02-06T06:04:07.381Z] Http2TestContext::handle Http2TestExchangeImpl: jdk.httpclient.test.lib.http2.Http2TestExchangeImpl@69f8fb55 [2025-02-06T06:04:07.381Z] HTTP_ChunkedHandler received request to http://127.0.0.1:54981/http2/chunk/y [2025-02-06T06:04:07.381Z] TestServer: [18 s, 126 ms, 82821 ns] Pushing promise: http://127.0.0.1:54981/http2/chunk/y/before/promise-1 [2025-02-06T06:04:07.381Z] TestServer: [18 s, 126 ms, 255851 ns] Pushing promise: http://127.0.0.1:54981/http2/chunk/y/after/promise-2 [2025-02-06T06:04:07.381Z] TestServer: [18 s, 126 ms, 388580 ns] Pushing promise: http://127.0.0.1:54981/http2/chunk/y/after/promise-3 [2025-02-06T06:04:07.381Z] test DependentPromiseActionsTest.testAsLinesAsync("http://127.0.0.1:54981/http2/chunk/y", true, SemaphoreStaller): success [2025-02-06T06:04:07.381Z] [2025-02-06T06:04:07.381Z] [18 s, 133 ms, 759431 ns] testAsLinesAsync(https://127.0.0.1:54983/https2/fixed/y, true, SemaphoreStaller) [2025-02-06T06:04:07.381Z] try stalling in BODY_HANDLER [2025-02-06T06:04:07.381Z] Http2TestContext::handle Http2TestExchangeImpl: jdk.httpclient.test.lib.http2.Http2TestExchangeImpl@484ee220 [2025-02-06T06:04:07.381Z] HTTP_FixedLengthHandler received request to https://127.0.0.1:54983/https2/fixed/y [2025-02-06T06:04:07.381Z] TestServer: [18 s, 172 ms, 665519 ns] Pushing promise: https://127.0.0.1:54983/https2/fixed/y/before/promise-1 [2025-02-06T06:04:07.381Z] TestServer: [18 s, 172 ms, 847560 ns] Pushing promise: https://127.0.0.1:54983/https2/fixed/y/after/promise-2 [2025-02-06T06:04:07.381Z] TestServer: [18 s, 172 ms, 977029 ns] Pushing promise: https://127.0.0.1:54983/https2/fixed/y/after/promise-3 [2025-02-06T06:04:07.381Z] test DependentPromiseActionsTest.testAsLinesAsync("https://127.0.0.1:54983/https2/fixed/y", true, SemaphoreStaller): success [2025-02-06T06:04:07.381Z] [2025-02-06T06:04:07.381Z] [18 s, 191 ms, 247971 ns] testAsLinesAsync(https://127.0.0.1:54983/https2/chunk/y, true, SemaphoreStaller) [2025-02-06T06:04:07.381Z] try stalling in BODY_HANDLER [2025-02-06T06:04:07.381Z] Http2TestContext::handle Http2TestExchangeImpl: jdk.httpclient.test.lib.http2.Http2TestExchangeImpl@667af823 [2025-02-06T06:04:07.381Z] HTTP_ChunkedHandler received request to https://127.0.0.1:54983/https2/chunk/y [2025-02-06T06:04:07.381Z] TestServer: [18 s, 193 ms, 922196 ns] Pushing promise: https://127.0.0.1:54983/https2/chunk/y/before/promise-1 [2025-02-06T06:04:07.381Z] TestServer: [18 s, 194 ms, 97481 ns] Pushing promise: https://127.0.0.1:54983/https2/chunk/y/after/promise-2 [2025-02-06T06:04:07.381Z] TestServer: [18 s, 194 ms, 269800 ns] Pushing promise: https://127.0.0.1:54983/https2/chunk/y/after/promise-3 [2025-02-06T06:04:07.381Z] test DependentPromiseActionsTest.testAsLinesAsync("https://127.0.0.1:54983/https2/chunk/y", true, SemaphoreStaller): success [2025-02-06T06:04:07.381Z] [2025-02-06T06:04:07.381Z] [18 s, 249 ms, 343616 ns] testAsStringAsync(http://127.0.0.1:54981/http2/fixed/y, false, SemaphoreStaller) [2025-02-06T06:04:07.381Z] try stalling in BODY_HANDLER [2025-02-06T06:04:07.381Z] Http2TestContext::handle Http2TestExchangeImpl: jdk.httpclient.test.lib.http2.Http2TestExchangeImpl@79640f02 [2025-02-06T06:04:07.381Z] HTTP_FixedLengthHandler received request to http://127.0.0.1:54981/http2/fixed/y [2025-02-06T06:04:07.381Z] TestServer: [18 s, 277 ms, 274732 ns] Pushing promise: http://127.0.0.1:54981/http2/fixed/y/before/promise-1 [2025-02-06T06:04:07.381Z] TestServer: [18 s, 277 ms, 467006 ns] Pushing promise: http://127.0.0.1:54981/http2/fixed/y/after/promise-2 [2025-02-06T06:04:07.381Z] TestServer: [18 s, 277 ms, 593926 ns] Pushing promise: http://127.0.0.1:54981/http2/fixed/y/after/promise-3 [2025-02-06T06:04:07.381Z] test DependentPromiseActionsTest.testAsStringAsync("http://127.0.0.1:54981/http2/fixed/y", false, SemaphoreStaller): success [2025-02-06T06:04:07.381Z] [2025-02-06T06:04:07.381Z] [18 s, 290 ms, 332624 ns] testAsStringAsync(http://127.0.0.1:54981/http2/chunk/y, false, SemaphoreStaller) [2025-02-06T06:04:07.381Z] try stalling in BODY_HANDLER [2025-02-06T06:04:07.381Z] Http2TestContext::handle Http2TestExchangeImpl: jdk.httpclient.test.lib.http2.Http2TestExchangeImpl@72ad0bcd [2025-02-06T06:04:07.381Z] HTTP_ChunkedHandler received request to http://127.0.0.1:54981/http2/chunk/y [2025-02-06T06:04:07.381Z] TestServer: [18 s, 307 ms, 372857 ns] Pushing promise: http://127.0.0.1:54981/http2/chunk/y/before/promise-1 [2025-02-06T06:04:07.381Z] TestServer: [18 s, 307 ms, 521333 ns] Pushing promise: http://127.0.0.1:54981/http2/chunk/y/after/promise-2 [2025-02-06T06:04:07.381Z] TestServer: [18 s, 307 ms, 634958 ns] Pushing promise: http://127.0.0.1:54981/http2/chunk/y/after/promise-3 [2025-02-06T06:04:07.381Z] test DependentPromiseActionsTest.testAsStringAsync("http://127.0.0.1:54981/http2/chunk/y", false, SemaphoreStaller): success [2025-02-06T06:04:07.381Z] [2025-02-06T06:04:07.381Z] [18 s, 319 ms, 917624 ns] testAsStringAsync(https://127.0.0.1:54983/https2/fixed/y, false, SemaphoreStaller) [2025-02-06T06:04:07.381Z] try stalling in BODY_HANDLER [2025-02-06T06:04:07.381Z] Http2TestContext::handle Http2TestExchangeImpl: jdk.httpclient.test.lib.http2.Http2TestExchangeImpl@2e1a1839 [2025-02-06T06:04:07.381Z] HTTP_FixedLengthHandler received request to https://127.0.0.1:54983/https2/fixed/y [2025-02-06T06:04:07.381Z] TestServer: [18 s, 366 ms, 835843 ns] Pushing promise: https://127.0.0.1:54983/https2/fixed/y/before/promise-1 [2025-02-06T06:04:07.381Z] TestServer: [18 s, 367 ms, 56190 ns] Pushing promise: https://127.0.0.1:54983/https2/fixed/y/after/promise-2 [2025-02-06T06:04:07.381Z] TestServer: [18 s, 367 ms, 180905 ns] Pushing promise: https://127.0.0.1:54983/https2/fixed/y/after/promise-3 [2025-02-06T06:04:07.381Z] test DependentPromiseActionsTest.testAsStringAsync("https://127.0.0.1:54983/https2/fixed/y", false, SemaphoreStaller): success [2025-02-06T06:04:07.381Z] [2025-02-06T06:04:07.381Z] [18 s, 424 ms, 363030 ns] testAsStringAsync(https://127.0.0.1:54983/https2/chunk/y, false, SemaphoreStaller) [2025-02-06T06:04:07.381Z] try stalling in BODY_HANDLER [2025-02-06T06:04:07.381Z] Http2TestContext::handle Http2TestExchangeImpl: jdk.httpclient.test.lib.http2.Http2TestExchangeImpl@d4c754d [2025-02-06T06:04:07.381Z] HTTP_ChunkedHandler received request to https://127.0.0.1:54983/https2/chunk/y [2025-02-06T06:04:07.381Z] TestServer: [18 s, 561 ms, 153366 ns] Pushing promise: https://127.0.0.1:54983/https2/chunk/y/before/promise-1 [2025-02-06T06:04:07.381Z] TestServer: [18 s, 561 ms, 301294 ns] Pushing promise: https://127.0.0.1:54983/https2/chunk/y/after/promise-2 [2025-02-06T06:04:07.381Z] TestServer: [18 s, 561 ms, 417999 ns] Pushing promise: https://127.0.0.1:54983/https2/chunk/y/after/promise-3 [2025-02-06T06:04:07.381Z] test DependentPromiseActionsTest.testAsStringAsync("https://127.0.0.1:54983/https2/chunk/y", false, SemaphoreStaller): success [2025-02-06T06:04:07.381Z] [2025-02-06T06:04:07.381Z] [18 s, 599 ms, 929931 ns] testAsStringAsync(http://127.0.0.1:54981/http2/fixed/y, true, SemaphoreStaller) [2025-02-06T06:04:07.381Z] try stalling in BODY_HANDLER [2025-02-06T06:04:07.381Z] Http2TestContext::handle Http2TestExchangeImpl: jdk.httpclient.test.lib.http2.Http2TestExchangeImpl@2509ca0a [2025-02-06T06:04:07.381Z] HTTP_FixedLengthHandler received request to http://127.0.0.1:54981/http2/fixed/y [2025-02-06T06:04:07.381Z] TestServer: [18 s, 603 ms, 278267 ns] Pushing promise: http://127.0.0.1:54981/http2/fixed/y/before/promise-1 [2025-02-06T06:04:07.381Z] TestServer: [18 s, 603 ms, 460728 ns] Pushing promise: http://127.0.0.1:54981/http2/fixed/y/after/promise-2 [2025-02-06T06:04:07.381Z] TestServer: [18 s, 603 ms, 586007 ns] Pushing promise: http://127.0.0.1:54981/http2/fixed/y/after/promise-3 [2025-02-06T06:04:07.381Z] test DependentPromiseActionsTest.testAsStringAsync("http://127.0.0.1:54981/http2/fixed/y", true, SemaphoreStaller): success [2025-02-06T06:04:07.381Z] [2025-02-06T06:04:07.381Z] [18 s, 621 ms, 889758 ns] testAsStringAsync(http://127.0.0.1:54981/http2/chunk/y, true, SemaphoreStaller) [2025-02-06T06:04:07.381Z] try stalling in BODY_HANDLER [2025-02-06T06:04:07.381Z] Http2TestContext::handle Http2TestExchangeImpl: jdk.httpclient.test.lib.http2.Http2TestExchangeImpl@2cfa680e [2025-02-06T06:04:07.381Z] HTTP_ChunkedHandler received request to http://127.0.0.1:54981/http2/chunk/y [2025-02-06T06:04:07.381Z] TestServer: [18 s, 624 ms, 728158 ns] Pushing promise: http://127.0.0.1:54981/http2/chunk/y/before/promise-1 [2025-02-06T06:04:07.381Z] TestServer: [18 s, 624 ms, 966769 ns] Pushing promise: http://127.0.0.1:54981/http2/chunk/y/after/promise-2 [2025-02-06T06:04:07.381Z] TestServer: [18 s, 625 ms, 183191 ns] Pushing promise: http://127.0.0.1:54981/http2/chunk/y/after/promise-3 [2025-02-06T06:04:07.381Z] test DependentPromiseActionsTest.testAsStringAsync("http://127.0.0.1:54981/http2/chunk/y", true, SemaphoreStaller): success [2025-02-06T06:04:07.381Z] [2025-02-06T06:04:07.381Z] [18 s, 650 ms, 604990 ns] testAsStringAsync(https://127.0.0.1:54983/https2/fixed/y, true, SemaphoreStaller) [2025-02-06T06:04:07.381Z] try stalling in BODY_HANDLER [2025-02-06T06:04:07.381Z] Http2TestContext::handle Http2TestExchangeImpl: jdk.httpclient.test.lib.http2.Http2TestExchangeImpl@23787a88 [2025-02-06T06:04:07.381Z] HTTP_FixedLengthHandler received request to https://127.0.0.1:54983/https2/fixed/y [2025-02-06T06:04:07.381Z] TestServer: [18 s, 664 ms, 121798 ns] Pushing promise: https://127.0.0.1:54983/https2/fixed/y/before/promise-1 [2025-02-06T06:04:07.381Z] TestServer: [18 s, 664 ms, 320799 ns] Pushing promise: https://127.0.0.1:54983/https2/fixed/y/after/promise-2 [2025-02-06T06:04:07.381Z] TestServer: [18 s, 664 ms, 445596 ns] Pushing promise: https://127.0.0.1:54983/https2/fixed/y/after/promise-3 [2025-02-06T06:04:07.381Z] test DependentPromiseActionsTest.testAsStringAsync("https://127.0.0.1:54983/https2/fixed/y", true, SemaphoreStaller): success [2025-02-06T06:04:07.381Z] [2025-02-06T06:04:07.381Z] [18 s, 704 ms, 124860 ns] testAsStringAsync(https://127.0.0.1:54983/https2/chunk/y, true, SemaphoreStaller) [2025-02-06T06:04:07.381Z] try stalling in BODY_HANDLER [2025-02-06T06:04:07.381Z] Http2TestContext::handle Http2TestExchangeImpl: jdk.httpclient.test.lib.http2.Http2TestExchangeImpl@7b4691bd [2025-02-06T06:04:07.381Z] HTTP_ChunkedHandler received request to https://127.0.0.1:54983/https2/chunk/y [2025-02-06T06:04:07.381Z] TestServer: [18 s, 705 ms, 692992 ns] Pushing promise: https://127.0.0.1:54983/https2/chunk/y/before/promise-1 [2025-02-06T06:04:07.381Z] TestServer: [18 s, 705 ms, 837596 ns] Pushing promise: https://127.0.0.1:54983/https2/chunk/y/after/promise-2 [2025-02-06T06:04:07.381Z] TestServer: [18 s, 705 ms, 958104 ns] Pushing promise: https://127.0.0.1:54983/https2/chunk/y/after/promise-3 [2025-02-06T06:04:07.381Z] test DependentPromiseActionsTest.testAsStringAsync("https://127.0.0.1:54983/https2/chunk/y", true, SemaphoreStaller): failure [2025-02-06T06:04:07.381Z] java.lang.AssertionError [2025-02-06T06:04:07.381Z] at DependentPromiseActionsTest.testDependent(DependentPromiseActionsTest.java:366) [2025-02-06T06:04:07.381Z] at DependentPromiseActionsTest.testDependent(DependentPromiseActionsTest.java:336) [2025-02-06T06:04:07.381Z] at DependentPromiseActionsTest.testAsStringAsync(DependentPromiseActionsTest.java:295) [2025-02-06T06:04:07.381Z] at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method) [2025-02-06T06:04:07.381Z] at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:77) [2025-02-06T06:04:07.381Z] at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) [2025-02-06T06:04:07.381Z] at java.base/java.lang.reflect.Method.invoke(Method.java:569) [2025-02-06T06:04:07.381Z] at org.testng.internal.MethodInvocationHelper.invokeMethod(MethodInvocationHelper.java:132) [2025-02-06T06:04:07.381Z] at org.testng.internal.TestInvoker.invokeMethod(TestInvoker.java:599) [2025-02-06T06:04:07.381Z] at org.testng.internal.TestInvoker.invokeTestMethod(TestInvoker.java:174) [2025-02-06T06:04:07.381Z] at org.testng.internal.MethodRunner.runInSequence(MethodRunner.java:46) [2025-02-06T06:04:07.381Z] at org.testng.internal.TestInvoker$MethodInvocationAgent.invoke(TestInvoker.java:822) [2025-02-06T06:04:07.381Z] at org.testng.internal.TestInvoker.invokeTestMethods(TestInvoker.java:147) [2025-02-06T06:04:07.381Z] at org.testng.internal.TestMethodWorker.invokeTestMethods(TestMethodWorker.java:146) [2025-02-06T06:04:07.381Z] at org.testng.internal.TestMethodWorker.run(TestMethodWorker.java:128) [2025-02-06T06:04:07.381Z] at java.base/java.util.ArrayList.forEach(ArrayList.java:1511) [2025-02-06T06:04:07.381Z] at org.testng.TestRunner.privateRun(TestRunner.java:764) [2025-02-06T06:04:07.381Z] at org.testng.TestRunner.run(TestRunner.java:585) [2025-02-06T06:04:07.381Z] at org.testng.SuiteRunner.runTest(SuiteRunner.java:384) [2025-02-06T06:04:07.381Z] at org.testng.SuiteRunner.runSequentially(SuiteRunner.java:378) [2025-02-06T06:04:07.381Z] at org.testng.SuiteRunner.privateRun(SuiteRunner.java:337) [2025-02-06T06:04:07.381Z] at org.testng.SuiteRunner.run(SuiteRunner.java:286) [2025-02-06T06:04:07.381Z] at org.testng.SuiteRunnerWorker.runSuite(SuiteRunnerWorker.java:53) [2025-02-06T06:04:07.381Z] at org.testng.SuiteRunnerWorker.run(SuiteRunnerWorker.java:96) [2025-02-06T06:04:07.381Z] at org.testng.TestNG.runSuitesSequentially(TestNG.java:1218) [2025-02-06T06:04:07.381Z] at org.testng.TestNG.runSuitesLocally(TestNG.java:1140) [2025-02-06T06:04:07.381Z] at org.testng.TestNG.runSuites(TestNG.java:1069) [2025-02-06T06:04:07.381Z] at org.testng.TestNG.run(TestNG.java:1037) [2025-02-06T06:04:07.381Z] at com.sun.javatest.regtest.agent.TestNGRunner.main(TestNGRunner.java:102) [2025-02-06T06:04:07.381Z] at com.sun.javatest.regtest.agent.TestNGRunner.main(TestNGRunner.java:58) [2025-02-06T06:04:07.381Z] at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method) [2025-02-06T06:04:07.381Z] at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:77) [2025-02-06T06:04:07.381Z] at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) [2025-02-06T06:04:07.381Z] at java.base/java.lang.reflect.Method.invoke(Method.java:569) [2025-02-06T06:04:07.381Z] at com.sun.javatest.regtest.agent.MainWrapper$MainTask.run(MainWrapper.java:138) [2025-02-06T06:04:07.381Z] at java.base/java.lang.Thread.run(Thread.java:840) [2025-02-06T06:04:07.381Z] [2025-02-06T06:04:07.381Z] testNoStalls(http://127.0.0.1:54981/http2/fixed/y, false) [2025-02-06T06:04:07.381Z] Http2TestContext::handle Http2TestExchangeImpl: jdk.httpclient.test.lib.http2.Http2TestExchangeImpl@5a1a49e6 [2025-02-06T06:04:07.381Z] HTTP_FixedLengthHandler received request to http://127.0.0.1:54981/http2/fixed/y [2025-02-06T06:04:07.381Z] TestServer: [18 s, 799 ms, 869588 ns] Pushing promise: http://127.0.0.1:54981/http2/fixed/y/before/promise-1 [2025-02-06T06:04:07.381Z] TestServer: [18 s, 800 ms, 52392 ns] Pushing promise: http://127.0.0.1:54981/http2/fixed/y/after/promise-2 [2025-02-06T06:04:07.381Z] TestServer: [18 s, 800 ms, 181834 ns] Pushing promise: http://127.0.0.1:54981/http2/fixed/y/after/promise-3 [2025-02-06T06:04:07.381Z] [18 s, 838 ms, 560601 ns] Received promise: http://127.0.0.1:54981/http2/fixed/y/after/promise-2 GET [2025-02-06T06:04:07.382Z] response: (GET http://127.0.0.1:54981/http2/fixed/y/after/promise-2) 200 [2025-02-06T06:04:07.382Z] [18 s, 839 ms, 5369 ns] Received promise: http://127.0.0.1:54981/http2/fixed/y/before/promise-1 GET [2025-02-06T06:04:07.382Z] response: (GET http://127.0.0.1:54981/http2/fixed/y/before/promise-1) 200 [2025-02-06T06:04:07.382Z] [18 s, 839 ms, 150200 ns] Received promise: http://127.0.0.1:54981/http2/fixed/y/after/promise-3 GET [2025-02-06T06:04:07.382Z] response: (GET http://127.0.0.1:54981/http2/fixed/y/after/promise-3) 200 [2025-02-06T06:04:07.382Z] test DependentPromiseActionsTest.testNoStalls("http://127.0.0.1:54981/http2/fixed/y", false): success [2025-02-06T06:04:07.382Z] [2025-02-06T06:04:07.382Z] testNoStalls(http://127.0.0.1:54981/http2/chunk/y, false) [2025-02-06T06:04:07.382Z] Http2TestContext::handle Http2TestExchangeImpl: jdk.httpclient.test.lib.http2.Http2TestExchangeImpl@443b47e7 [2025-02-06T06:04:07.382Z] HTTP_ChunkedHandler received request to http://127.0.0.1:54981/http2/chunk/y [2025-02-06T06:04:07.382Z] TestServer: [18 s, 879 ms, 672426 ns] Pushing promise: http://127.0.0.1:54981/http2/chunk/y/before/promise-1 [2025-02-06T06:04:07.382Z] TestServer: [18 s, 879 ms, 824397 ns] Pushing promise: http://127.0.0.1:54981/http2/chunk/y/after/promise-2 [2025-02-06T06:04:07.382Z] TestServer: [18 s, 879 ms, 936019 ns] Pushing promise: http://127.0.0.1:54981/http2/chunk/y/after/promise-3 [2025-02-06T06:04:07.382Z] [18 s, 923 ms, 105669 ns] Received promise: http://127.0.0.1:54981/http2/chunk/y/after/promise-3 GET [2025-02-06T06:04:07.382Z] response: (GET http://127.0.0.1:54981/http2/chunk/y/after/promise-3) 200 [2025-02-06T06:04:07.382Z] [18 s, 923 ms, 891035 ns] Received promise: http://127.0.0.1:54981/http2/chunk/y/before/promise-1 GET [2025-02-06T06:04:07.382Z] response: (GET http://127.0.0.1:54981/http2/chunk/y/before/promise-1) 200 [2025-02-06T06:04:07.382Z] [18 s, 925 ms, 758420 ns] Received promise: http://127.0.0.1:54981/http2/chunk/y/after/promise-2 GET [2025-02-06T06:04:07.382Z] response: (GET http://127.0.0.1:54981/http2/chunk/y/after/promise-2) 200 [2025-02-06T06:04:07.382Z] test DependentPromiseActionsTest.testNoStalls("http://127.0.0.1:54981/http2/chunk/y", false): success [2025-02-06T06:04:07.382Z] [2025-02-06T06:04:07.382Z] testNoStalls(https://127.0.0.1:54983/https2/fixed/y, false) [2025-02-06T06:04:07.382Z] Http2TestContext::handle Http2TestExchangeImpl: jdk.httpclient.test.lib.http2.Http2TestExchangeImpl@5b986dbf [2025-02-06T06:04:07.382Z] HTTP_FixedLengthHandler received request to https://127.0.0.1:54983/https2/fixed/y [2025-02-06T06:04:07.382Z] TestServer: [18 s, 987 ms, 706289 ns] Pushing promise: https://127.0.0.1:54983/https2/fixed/y/before/promise-1 [2025-02-06T06:04:07.382Z] TestServer: [18 s, 987 ms, 900323 ns] Pushing promise: https://127.0.0.1:54983/https2/fixed/y/after/promise-2 [2025-02-06T06:04:07.382Z] TestServer: [18 s, 988 ms, 51649 ns] Pushing promise: https://127.0.0.1:54983/https2/fixed/y/after/promise-3 [2025-02-06T06:04:07.382Z] [19 s, 1 ms, 227610 ns] Received promise: https://127.0.0.1:54983/https2/fixed/y/before/promise-1 GET [2025-02-06T06:04:07.382Z] response: (GET https://127.0.0.1:54983/https2/fixed/y/before/promise-1) 200 [2025-02-06T06:04:07.382Z] [19 s, 6 ms, 911199 ns] Received promise: https://127.0.0.1:54983/https2/fixed/y/after/promise-3 GET [2025-02-06T06:04:07.382Z] response: (GET https://127.0.0.1:54983/https2/fixed/y/after/promise-3) 200 [2025-02-06T06:04:07.382Z] [19 s, 23 ms, 505678 ns] Received promise: https://127.0.0.1:54983/https2/fixed/y/after/promise-2 GET [2025-02-06T06:04:07.382Z] response: (GET https://127.0.0.1:54983/https2/fixed/y/after/promise-2) 200 [2025-02-06T06:04:07.382Z] test DependentPromiseActionsTest.testNoStalls("https://127.0.0.1:54983/https2/fixed/y", false): success [2025-02-06T06:04:07.382Z] [2025-02-06T06:04:07.382Z] testNoStalls(https://127.0.0.1:54983/https2/chunk/y, false) [2025-02-06T06:04:07.382Z] Http2TestContext::handle Http2TestExchangeImpl: jdk.httpclient.test.lib.http2.Http2TestExchangeImpl@3c8bdb6c [2025-02-06T06:04:07.382Z] HTTP_ChunkedHandler received request to https://127.0.0.1:54983/https2/chunk/y [2025-02-06T06:04:07.382Z] TestServer: [19 s, 63 ms, 719988 ns] Pushing promise: https://127.0.0.1:54983/https2/chunk/y/before/promise-1 [2025-02-06T06:04:07.382Z] TestServer: [19 s, 63 ms, 865934 ns] Pushing promise: https://127.0.0.1:54983/https2/chunk/y/after/promise-2 [2025-02-06T06:04:07.382Z] TestServer: [19 s, 63 ms, 979640 ns] Pushing promise: https://127.0.0.1:54983/https2/chunk/y/after/promise-3 [2025-02-06T06:04:07.382Z] [19 s, 78 ms, 973338 ns] Received promise: https://127.0.0.1:54983/https2/chunk/y/after/promise-2 GET [2025-02-06T06:04:07.382Z] response: (GET https://127.0.0.1:54983/https2/chunk/y/after/promise-2) 200 [2025-02-06T06:04:07.382Z] [19 s, 82 ms, 394007 ns] Received promise: https://127.0.0.1:54983/https2/chunk/y/before/promise-1 GET [2025-02-06T06:04:07.382Z] response: (GET https://127.0.0.1:54983/https2/chunk/y/before/promise-1) 200 [2025-02-06T06:04:07.382Z] [19 s, 110 ms, 976617 ns] Received promise: https://127.0.0.1:54983/https2/chunk/y/after/promise-3 GET [2025-02-06T06:04:07.382Z] response: (GET https://127.0.0.1:54983/https2/chunk/y/after/promise-3) 200 [2025-02-06T06:04:07.382Z] test DependentPromiseActionsTest.testNoStalls("https://127.0.0.1:54983/https2/chunk/y", false): success [2025-02-06T06:04:07.382Z] [2025-02-06T06:04:07.382Z] testNoStalls(http://127.0.0.1:54981/http2/fixed/y, true) [2025-02-06T06:04:07.382Z] Http2TestContext::handle Http2TestExchangeImpl: jdk.httpclient.test.lib.http2.Http2TestExchangeImpl@1f18dcc1 [2025-02-06T06:04:07.382Z] HTTP_FixedLengthHandler received request to http://127.0.0.1:54981/http2/fixed/y [2025-02-06T06:04:07.382Z] TestServer: [19 s, 113 ms, 515544 ns] Pushing promise: http://127.0.0.1:54981/http2/fixed/y/before/promise-1 [2025-02-06T06:04:07.382Z] TestServer: [19 s, 113 ms, 707116 ns] Pushing promise: http://127.0.0.1:54981/http2/fixed/y/after/promise-2 [2025-02-06T06:04:07.382Z] TestServer: [19 s, 113 ms, 831610 ns] Pushing promise: http://127.0.0.1:54981/http2/fixed/y/after/promise-3 [2025-02-06T06:04:07.382Z] [19 s, 136 ms, 951000 ns] Received promise: http://127.0.0.1:54981/http2/fixed/y/after/promise-2 GET [2025-02-06T06:04:07.382Z] response: (GET http://127.0.0.1:54981/http2/fixed/y/after/promise-2) 200 [2025-02-06T06:04:07.382Z] [19 s, 137 ms, 539853 ns] Received promise: http://127.0.0.1:54981/http2/fixed/y/before/promise-1 GET [2025-02-06T06:04:07.382Z] response: (GET http://127.0.0.1:54981/http2/fixed/y/before/promise-1) 200 [2025-02-06T06:04:07.382Z] [19 s, 138 ms, 560755 ns] Received promise: http://127.0.0.1:54981/http2/fixed/y/after/promise-3 GET [2025-02-06T06:04:07.382Z] response: (GET http://127.0.0.1:54981/http2/fixed/y/after/promise-3) 200 [2025-02-06T06:04:07.382Z] test DependentPromiseActionsTest.testNoStalls("http://127.0.0.1:54981/http2/fixed/y", true): success [2025-02-06T06:04:07.382Z] [2025-02-06T06:04:07.382Z] testNoStalls(http://127.0.0.1:54981/http2/chunk/y, true) [2025-02-06T06:04:07.382Z] Http2TestContext::handle Http2TestExchangeImpl: jdk.httpclient.test.lib.http2.Http2TestExchangeImpl@5eafab26 [2025-02-06T06:04:07.382Z] HTTP_ChunkedHandler received request to http://127.0.0.1:54981/http2/chunk/y [2025-02-06T06:04:07.382Z] TestServer: [19 s, 150 ms, 819724 ns] Pushing promise: http://127.0.0.1:54981/http2/chunk/y/before/promise-1 [2025-02-06T06:04:07.382Z] TestServer: [19 s, 151 ms, 612313 ns] Pushing promise: http://127.0.0.1:54981/http2/chunk/y/after/promise-2 [2025-02-06T06:04:07.382Z] TestServer: [19 s, 152 ms, 308040 ns] Pushing promise: http://127.0.0.1:54981/http2/chunk/y/after/promise-3 [2025-02-06T06:04:07.382Z] [19 s, 185 ms, 121633 ns] Received promise: http://127.0.0.1:54981/http2/chunk/y/after/promise-3 GET [2025-02-06T06:04:07.382Z] response: (GET http://127.0.0.1:54981/http2/chunk/y/after/promise-3) 200 [2025-02-06T06:04:07.382Z] [19 s, 212 ms, 225727 ns] Received promise: http://127.0.0.1:54981/http2/chunk/y/before/promise-1 GET [2025-02-06T06:04:07.382Z] response: (GET http://127.0.0.1:54981/http2/chunk/y/before/promise-1) 200 [2025-02-06T06:04:07.382Z] [19 s, 212 ms, 673249 ns] Received promise: http://127.0.0.1:54981/http2/chunk/y/after/promise-2 GET [2025-02-06T06:04:07.382Z] response: (GET http://127.0.0.1:54981/http2/chunk/y/after/promise-2) 200 [2025-02-06T06:04:07.382Z] test DependentPromiseActionsTest.testNoStalls("http://127.0.0.1:54981/http2/chunk/y", true): success [2025-02-06T06:04:07.382Z] [2025-02-06T06:04:07.382Z] testNoStalls(https://127.0.0.1:54983/https2/fixed/y, true) [2025-02-06T06:04:07.382Z] Http2TestContext::handle Http2TestExchangeImpl: jdk.httpclient.test.lib.http2.Http2TestExchangeImpl@36b613f [2025-02-06T06:04:07.382Z] HTTP_FixedLengthHandler received request to https://127.0.0.1:54983/https2/fixed/y [2025-02-06T06:04:07.382Z] TestServer: [19 s, 225 ms, 752233 ns] Pushing promise: https://127.0.0.1:54983/https2/fixed/y/before/promise-1 [2025-02-06T06:04:07.382Z] TestServer: [19 s, 226 ms, 249105 ns] Pushing promise: https://127.0.0.1:54983/https2/fixed/y/after/promise-2 [2025-02-06T06:04:07.382Z] TestServer: [19 s, 226 ms, 676743 ns] Pushing promise: https://127.0.0.1:54983/https2/fixed/y/after/promise-3 [2025-02-06T06:04:07.382Z] [19 s, 248 ms, 81823 ns] Received promise: https://127.0.0.1:54983/https2/fixed/y/before/promise-1 GET [2025-02-06T06:04:07.382Z] response: (GET https://127.0.0.1:54983/https2/fixed/y/before/promise-1) 200 [2025-02-06T06:04:07.382Z] [19 s, 263 ms, 567617 ns] Received promise: https://127.0.0.1:54983/https2/fixed/y/after/promise-3 GET [2025-02-06T06:04:07.382Z] response: (GET https://127.0.0.1:54983/https2/fixed/y/after/promise-3) 200 [2025-02-06T06:04:07.382Z] [19 s, 264 ms, 262969 ns] Received promise: https://127.0.0.1:54983/https2/fixed/y/after/promise-2 GET [2025-02-06T06:04:07.382Z] response: (GET https://127.0.0.1:54983/https2/fixed/y/after/promise-2) 200 [2025-02-06T06:04:07.382Z] test DependentPromiseActionsTest.testNoStalls("https://127.0.0.1:54983/https2/fixed/y", true): success [2025-02-06T06:04:07.382Z] [2025-02-06T06:04:07.382Z] testNoStalls(https://127.0.0.1:54983/https2/chunk/y, true) [2025-02-06T06:04:07.382Z] Http2TestContext::handle Http2TestExchangeImpl: jdk.httpclient.test.lib.http2.Http2TestExchangeImpl@6d638a02 [2025-02-06T06:04:07.382Z] HTTP_ChunkedHandler received request to https://127.0.0.1:54983/https2/chunk/y [2025-02-06T06:04:07.382Z] TestServer: [19 s, 277 ms, 486047 ns] Pushing promise: https://127.0.0.1:54983/https2/chunk/y/before/promise-1 [2025-02-06T06:04:07.382Z] TestServer: [19 s, 277 ms, 651821 ns] Pushing promise: https://127.0.0.1:54983/https2/chunk/y/after/promise-2 [2025-02-06T06:04:07.382Z] TestServer: [19 s, 278 ms, 343889 ns] Pushing promise: https://127.0.0.1:54983/https2/chunk/y/after/promise-3 [2025-02-06T06:04:07.382Z] [19 s, 284 ms, 520589 ns] Received promise: https://127.0.0.1:54983/https2/chunk/y/after/promise-2 GET [2025-02-06T06:04:07.382Z] response: (GET https://127.0.0.1:54983/https2/chunk/y/after/promise-2) 200 [2025-02-06T06:04:07.382Z] [19 s, 285 ms, 164621 ns] Received promise: https://127.0.0.1:54983/https2/chunk/y/before/promise-1 GET [2025-02-06T06:04:07.382Z] response: (GET https://127.0.0.1:54983/https2/chunk/y/before/promise-1) 200 [2025-02-06T06:04:07.382Z] [19 s, 285 ms, 297610 ns] Received promise: https://127.0.0.1:54983/https2/chunk/y/after/promise-3 GET [2025-02-06T06:04:07.382Z] response: (GET https://127.0.0.1:54983/https2/chunk/y/after/promise-3) 200 [2025-02-06T06:04:07.382Z] test DependentPromiseActionsTest.testNoStalls("https://127.0.0.1:54983/https2/chunk/y", true): success [2025-02-06T06:04:07.382Z] [2025-02-06T06:04:07.382Z] ========================= [2025-02-06T06:04:07.382Z] [2025-02-06T06:04:07.382Z] [19 s, 331 ms, 242585 ns] Created 4 servers and 17 clients [2025-02-06T06:04:07.382Z] Failed tests: [2025-02-06T06:04:07.382Z] testAsStringAsync(https://127.0.0.1:54983/https2/chunk/y, true, SemaphoreStaller): java.lang.AssertionError [2025-02-06T06:04:07.382Z] java.lang.AssertionError [2025-02-06T06:04:07.382Z] at DependentPromiseActionsTest.testDependent(DependentPromiseActionsTest.java:366) [2025-02-06T06:04:07.382Z] at DependentPromiseActionsTest.testDependent(DependentPromiseActionsTest.java:336) [2025-02-06T06:04:07.382Z] at DependentPromiseActionsTest.testAsStringAsync(DependentPromiseActionsTest.java:295) [2025-02-06T06:04:07.382Z] at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method) [2025-02-06T06:04:07.382Z] at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:77) [2025-02-06T06:04:07.382Z] at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) [2025-02-06T06:04:07.382Z] at java.base/java.lang.reflect.Method.invoke(Method.java:569) [2025-02-06T06:04:07.382Z] at org.testng.internal.MethodInvocationHelper.invokeMethod(MethodInvocationHelper.java:132) [2025-02-06T06:04:07.382Z] at org.testng.internal.TestInvoker.invokeMethod(TestInvoker.java:599) [2025-02-06T06:04:07.382Z] at org.testng.internal.TestInvoker.invokeTestMethod(TestInvoker.java:174) [2025-02-06T06:04:07.382Z] at org.testng.internal.MethodRunner.runInSequence(MethodRunner.java:46) [2025-02-06T06:04:07.382Z] at org.testng.internal.TestInvoker$MethodInvocationAgent.invoke(TestInvoker.java:822) [2025-02-06T06:04:07.382Z] at org.testng.internal.TestInvoker.invokeTestMethods(TestInvoker.java:147) [2025-02-06T06:04:07.382Z] at org.testng.internal.TestMethodWorker.invokeTestMethods(TestMethodWorker.java:146) [2025-02-06T06:04:07.382Z] at org.testng.internal.TestMethodWorker.run(TestMethodWorker.java:128) [2025-02-06T06:04:07.382Z] at java.base/java.util.ArrayList.forEach(ArrayList.java:1511) [2025-02-06T06:04:07.382Z] at org.testng.TestRunner.privateRun(TestRunner.java:764) [2025-02-06T06:04:07.382Z] at org.testng.TestRunner.run(TestRunner.java:585) [2025-02-06T06:04:07.382Z] at org.testng.SuiteRunner.runTest(SuiteRunner.java:384) [2025-02-06T06:04:07.382Z] at org.testng.SuiteRunner.runSequentially(SuiteRunner.java:378) [2025-02-06T06:04:07.382Z] at org.testng.SuiteRunner.privateRun(SuiteRunner.java:337) [2025-02-06T06:04:07.382Z] at org.testng.SuiteRunner.run(SuiteRunner.java:286) [2025-02-06T06:04:07.382Z] at org.testng.SuiteRunnerWorker.runSuite(SuiteRunnerWorker.java:53) [2025-02-06T06:04:07.382Z] at org.testng.SuiteRunnerWorker.run(SuiteRunnerWorker.java:96) [2025-02-06T06:04:07.382Z] at org.testng.TestNG.runSuitesSequentially(TestNG.java:1218) [2025-02-06T06:04:07.382Z] at org.testng.TestNG.runSuitesLocally(TestNG.java:1140) [2025-02-06T06:04:07.382Z] at org.testng.TestNG.runSuites(TestNG.java:1069) [2025-02-06T06:04:07.382Z] at org.testng.TestNG.run(TestNG.java:1037) [2025-02-06T06:04:07.382Z] at com.sun.javatest.regtest.agent.TestNGRunner.main(TestNGRunner.java:102) [2025-02-06T06:04:07.382Z] at com.sun.javatest.regtest.agent.TestNGRunner.main(TestNGRunner.java:58) [2025-02-06T06:04:07.382Z] at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method) [2025-02-06T06:04:07.382Z] at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:77) [2025-02-06T06:04:07.382Z] at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) [2025-02-06T06:04:07.382Z] at java.base/java.lang.reflect.Method.invoke(Method.java:569) [2025-02-06T06:04:07.382Z] at com.sun.javatest.regtest.agent.MainWrapper$MainTask.run(MainWrapper.java:138) [2025-02-06T06:04:07.382Z] at java.base/java.lang.Thread.run(Thread.java:840) [2025-02-06T06:04:07.382Z] [2025-02-06T06:04:07.382Z] ========================= [2025-02-06T06:04:07.382Z] [2025-02-06T06:04:07.382Z] config DependentPromiseActionsTest.printFailedTests(): success [2025-02-06T06:04:07.382Z] Http2TestServerImpl: stop [2025-02-06T06:04:07.382Z] Http2TestServerImpl: stop [2025-02-06T06:04:07.382Z] config DependentPromiseActionsTest.teardown(): success [2025-02-06T06:04:07.382Z] [2025-02-06T06:04:07.382Z] =============================================== [2025-02-06T06:04:07.382Z] java/net/httpclient/DependentPromiseActionsTest.java [2025-02-06T06:04:07.382Z] Total tests run: 32, Passes: 31, Failures: 1, Skips: 0 [2025-02-06T06:04:07.382Z] =============================================== [2025-02-06T06:04:07.382Z] [2025-02-06T06:04:07.382Z] STDERR: [2025-02-06T06:04:07.382Z] DEBUG: [MainThread] [35ms] HttpClientImpl(1) proxySelector is sun.net.spi.DefaultProxySelector@53e28e19 (user-supplied=false) [2025-02-06T06:04:07.382Z] DEBUG: [MainThread] [135ms] HttpClientImpl(1) ClientImpl (async) send http://127.0.0.1:54981/http2/fixed/y GET [2025-02-06T06:04:07.382Z] DEBUG: [pool-1-thread-1] [232ms] Exchange establishing exchange for http://127.0.0.1:54981/http2/fixed/y GET, [2025-02-06T06:04:07.382Z] proxy=null [2025-02-06T06:04:07.382Z] DEBUG: [pool-1-thread-1] [320ms] Http2ClientImpl not found in connection pool [2025-02-06T06:04:07.382Z] DEBUG: [pool-1-thread-1] [321ms] ExchangeImpl get: Trying to get HTTP/2 connection [2025-02-06T06:04:07.382Z] DEBUG: [pool-1-thread-1] [321ms] ExchangeImpl handling HTTP/2 connection creation result [2025-02-06T06:04:07.382Z] DEBUG: [pool-1-thread-1] [321ms] ExchangeImpl new Http1Exchange, try to upgrade [2025-02-06T06:04:07.382Z] DEBUG: [pool-1-thread-1] [417ms] PlainHttpConnection(?) Initial receive buffer size is: 131072 [2025-02-06T06:04:07.382Z] DEBUG: [pool-1-thread-1] [418ms] PlainHttpConnection(?) Initial send buffer size is: 131072 [2025-02-06T06:04:07.382Z] DEBUG: [pool-1-thread-1] [426ms] Exchange checkFor407: all clear [2025-02-06T06:04:07.382Z] DEBUG: [pool-1-thread-1] [455ms] Http1Exchange Sending headers only [2025-02-06T06:04:07.382Z] DEBUG: [pool-1-thread-1] [458ms] Http1AsyncReceiver(SocketTube(1)) Subscribed pending jdk.internal.net.http.Http1Response$HeadersReader@7ce1744a queue.isEmpty: true [2025-02-06T06:04:07.382Z] DEBUG: [pool-1-thread-1] [527ms] Http1AsyncReceiver(SocketTube(1)) delegate is now jdk.internal.net.http.Http1Response$HeadersReader@7ce1744a, demand=1, canRequestMore=true, queue.isEmpty=true [2025-02-06T06:04:07.384Z] DEBUG: [pool-1-thread-1] [527ms] Http1AsyncReceiver(SocketTube(1)) downstream subscription demand is 1 [2025-02-06T06:04:07.384Z] DEBUG: [pool-1-thread-1] [549ms] Http1AsyncReceiver(SocketTube(1)) checkRequestMore: canRequestMore=true, hasDemand=true [2025-02-06T06:04:07.384Z] DEBUG: [pool-1-thread-1] [549ms] Http1AsyncReceiver(SocketTube(1)) downstream subscription demand is 1 [2025-02-06T06:04:07.384Z] DEBUG: [pool-1-thread-1] [549ms] Http1AsyncReceiver(SocketTube(1)) checkRequestMore: canRequestMore=true, hasDemand=true [2025-02-06T06:04:07.384Z] DEBUG: [pool-1-thread-1] [549ms] Http1Exchange response created in advance [2025-02-06T06:04:07.384Z] DEBUG: [pool-1-thread-1] [549ms] Http1Exchange initiating connect async [2025-02-06T06:04:07.384Z] DEBUG: [pool-1-thread-1] [626ms] PlainHttpConnection(SocketTube(1)) registering connect event [2025-02-06T06:04:07.384Z] DEBUG: [HttpClient-1-SelectorManager] [645ms] SelectorAttachment Registering jdk.internal.net.http.PlainHttpConnection$ConnectEvent@1706e2e for 8 (true) [2025-02-06T06:04:07.384Z] DEBUG: [HttpClient-1-SelectorManager] [647ms] PlainHttpConnection(SocketTube(1)) ConnectEvent: finishing connect [2025-02-06T06:04:07.385Z] DEBUG: [HttpClient-1-SelectorManager] [648ms] PlainHttpConnection(SocketTube(1)) ConnectEvent: connect finished: true, cancelled: false, Local addr: /127.0.0.1:54984 [2025-02-06T06:04:07.385Z] DEBUG: [pool-1-thread-1] [650ms] PlainHttpConnection(SocketTube(1)) finishConnect, setting connected=true [2025-02-06T06:04:07.385Z] TestServer: New connection from Socket[addr=/127.0.0.1,port=54984,localport=54981] [2025-02-06T06:04:07.385Z] DEBUG: [pool-1-thread-1] [650ms] Http1Exchange SocketTube(1) connecting flows [2025-02-06T06:04:07.385Z] DEBUG: [pool-1-thread-1] [650ms] SocketTube(1) connecting flows [2025-02-06T06:04:07.385Z] DEBUG: [pool-1-thread-1] [650ms] SocketTube(1) read publisher got subscriber [2025-02-06T06:04:07.385Z] DEBUG: [pool-1-thread-1] [650ms] SocketTube(1) registering subscribe event [2025-02-06T06:04:07.385Z] DEBUG: [pool-1-thread-1] [651ms] SocketTube(1) leaving read.subscribe: Reading: [ops=0, demand=0, stopped=false], Writing: [ops=0, demand=0] [2025-02-06T06:04:07.385Z] DEBUG: [HttpClient-1-SelectorManager] [651ms] SocketTube(1) subscribe event raised [2025-02-06T06:04:07.385Z] DEBUG: [HttpClient-1-SelectorManager] [651ms] SocketTube(1) handling pending subscription for jdk.internal.net.http.Http1AsyncReceiver$Http1TubeSubscriber@249d98f5 [2025-02-06T06:04:07.385Z] DEBUG: [HttpClient-1-SelectorManager] [651ms] SocketTube(1) read demand reset to 0 [2025-02-06T06:04:07.385Z] DEBUG: [HttpClient-1-SelectorManager] [651ms] SocketTube(1) calling onSubscribe [2025-02-06T06:04:07.385Z] DEBUG: [pool-1-thread-1] [651ms] Http1Publisher(SocketTube(1)) got subscriber: SocketTube(1) [2025-02-06T06:04:07.385Z] DEBUG: [HttpClient-1-SelectorManager] [651ms] Http1AsyncReceiver(SocketTube(1)) Received onSubscribed from upstream [2025-02-06T06:04:07.385Z] DEBUG: [HttpClient-1-SelectorManager] [662ms] SocketTube(1) onSubscribe called [2025-02-06T06:04:07.385Z] DEBUG: [HttpClient-1-SelectorManager] [662ms] SocketTube(1) pending subscriber subscribed [2025-02-06T06:04:07.385Z] DEBUG: [pool-1-thread-1] [651ms] SocketTube(1) subscribed for writing [2025-02-06T06:04:07.385Z] DEBUG: [pool-1-thread-2] [667ms] Http1AsyncReceiver(SocketTube(1)) downstream subscription demand is 1 [2025-02-06T06:04:07.385Z] DEBUG: [pool-1-thread-2] [692ms] Http1AsyncReceiver(SocketTube(1)) checkRequestMore: canRequestMore=true, hasDemand=true [2025-02-06T06:04:07.385Z] DEBUG: [pool-1-thread-2] [692ms] Http1AsyncReceiver(SocketTube(1)) Http1TubeSubscriber: requesting one more from upstream [2025-02-06T06:04:07.385Z] DEBUG: [pool-1-thread-2] [693ms] SocketTube(1) got some demand for reading [2025-02-06T06:04:07.385Z] DEBUG: [pool-1-thread-2] [693ms] SocketTube(1) resuming read event [2025-02-06T06:04:07.385Z] DEBUG: [pool-1-thread-2] [695ms] SocketTube(1) leaving request(1): Reading: [ops=1, demand=1, stopped=false], Writing: [ops=0, demand=0] [2025-02-06T06:04:07.385Z] DEBUG: [HttpClient-1-SelectorManager] [696ms] SelectorAttachment Registering jdk.internal.net.http.SocketTube$InternalReadPublisher$ReadEvent@3854c37e for 1 (true) [2025-02-06T06:04:07.385Z] DEBUG: [pool-1-thread-1] [693ms] SocketTube(1) write: registering startSubscription event [2025-02-06T06:04:07.385Z] DEBUG: [pool-1-thread-1] [760ms] Http1Exchange requestAction.headers [2025-02-06T06:04:07.385Z] DEBUG: [HttpClient-1-SelectorManager] [761ms] SocketTube(1) write: starting subscription [2025-02-06T06:04:07.385Z] DEBUG: [HttpClient-1-SelectorManager] [792ms] SocketTube(1) write: offloading requestMore [2025-02-06T06:04:07.385Z] DEBUG: [pool-1-thread-1] [791ms] Http1Exchange setting outgoing with headers [2025-02-06T06:04:07.385Z] DEBUG: [pool-1-thread-1] [817ms] Http1Exchange appending to outgoing DataPair [data=[java.nio.HeapByteBuffer[pos=0 lim=233 cap=233]], throwable=null] [2025-02-06T06:04:07.385Z] DEBUG: [pool-1-thread-1] [817ms] Http1Publisher(SocketTube(1)) WriteTask [2025-02-06T06:04:07.385Z] DEBUG: [pool-1-thread-2] [825ms] SocketTube(1) write: requesting more... [2025-02-06T06:04:07.385Z] DEBUG: [pool-1-thread-2] [825ms] Http1Publisher(SocketTube(1)) subscription request(1), demand=1 [2025-02-06T06:04:07.385Z] DEBUG: [pool-1-thread-2] [825ms] SocketTube(1) leaving requestMore: Reading: [ops=1, demand=1, stopped=false], Writing: [ops=0, demand=1] [2025-02-06T06:04:07.385Z] DEBUG: [pool-1-thread-1] [826ms] Http1Publisher(SocketTube(1)) hasOutgoing = true [2025-02-06T06:04:07.385Z] DEBUG: [pool-1-thread-1] [827ms] Http1Exchange initiating completion of headersSentCF [2025-02-06T06:04:07.385Z] DEBUG: [pool-1-thread-1] [830ms] Http1Publisher(SocketTube(1)) onNext with 233 bytes [2025-02-06T06:04:07.385Z] DEBUG: [pool-1-thread-1] [831ms] SocketTube(1) trying to write: 233 [2025-02-06T06:04:07.385Z] DEBUG: [pool-1-thread-1] [835ms] SocketTube(1) wrote: 233 [2025-02-06T06:04:07.385Z] DEBUG: [pool-1-thread-1] [846ms] SocketTube(1) write: requesting more... [2025-02-06T06:04:07.385Z] DEBUG: [pool-1-thread-1] [846ms] Http1Publisher(SocketTube(1)) subscription request(1), demand=1 [2025-02-06T06:04:07.385Z] DEBUG: [pool-1-thread-1] [847ms] SocketTube(1) leaving requestMore: Reading: [ops=1, demand=1, stopped=false], Writing: [ops=0, demand=1] [2025-02-06T06:04:07.385Z] DEBUG: [pool-1-thread-1] [847ms] SocketTube(1) leaving w.onNext Reading: [ops=1, demand=1, stopped=false], Writing: [ops=0, demand=1] [2025-02-06T06:04:07.385Z] DEBUG: [pool-1-thread-1] [848ms] Http1Publisher(SocketTube(1)) WriteTask [2025-02-06T06:04:07.385Z] DEBUG: [pool-1-thread-1] [848ms] Http1Publisher(SocketTube(1)) hasOutgoing = false [2025-02-06T06:04:07.385Z] DEBUG: [pool-1-thread-1] [851ms] Exchange checkFor407: all clear [2025-02-06T06:04:07.385Z] DEBUG: [pool-1-thread-1] [852ms] Exchange sendRequestBody [2025-02-06T06:04:07.385Z] DEBUG: [pool-1-thread-1] [852ms] Http1Exchange sendBodyAsync [2025-02-06T06:04:07.385Z] DEBUG: [pool-1-thread-1] [853ms] Http1Exchange bodySubscriber is null [2025-02-06T06:04:07.385Z] DEBUG: [pool-1-thread-1] [853ms] Http1Exchange appending to outgoing DataPair [data=[java.nio.HeapByteBuffer[pos=0 lim=0 cap=0]], throwable=null] [2025-02-06T06:04:07.385Z] DEBUG: [pool-1-thread-1] [854ms] Http1Publisher(SocketTube(1)) WriteTask [2025-02-06T06:04:07.385Z] DEBUG: [pool-1-thread-1] [855ms] Http1Publisher(SocketTube(1)) hasOutgoing = true [2025-02-06T06:04:07.385Z] DEBUG: [HttpClient-1-SelectorManager] [981ms] SelectorAttachment Registering jdk.internal.net.http.SocketTube$InternalReadPublisher$ReadEvent@3854c37e for 0 (false) [2025-02-06T06:04:07.385Z] DEBUG: [HttpClient-1-SelectorManager] [984ms] SocketTube(1) read bytes: 71 [2025-02-06T06:04:07.385Z] DEBUG: [HttpClient-1-SelectorManager] [984ms] Http1AsyncReceiver(SocketTube(1)) Putting 71 bytes into the queue [2025-02-06T06:04:07.385Z] DEBUG: [HttpClient-1-SelectorManager] [994ms] SocketTube(1) resuming read event [2025-02-06T06:04:07.385Z] DEBUG: [HttpClient-1-SelectorManager] [995ms] SelectorAttachment Registering jdk.internal.net.http.SocketTube$InternalReadPublisher$ReadEvent@3854c37e for 1 (false) [2025-02-06T06:04:07.385Z] DEBUG: [HttpClient-1-SelectorManager] [995ms] SocketTube(1) leaving read() loop after onNext: Reading: [ops=1, demand=0, stopped=false], Writing: [ops=0, demand=1] [2025-02-06T06:04:07.385Z] DEBUG: [pool-1-thread-2] [998ms] Http1AsyncReceiver(SocketTube(1)) Got 71 bytes for delegate jdk.internal.net.http.Http1Response$HeadersReader@7ce1744a [2025-02-06T06:04:07.385Z] DEBUG: [pool-1-thread-2] [998ms] Http1AsyncReceiver(SocketTube(1)) downstream subscription demand is 1 [2025-02-06T06:04:07.385Z] DEBUG: [pool-1-thread-2] [999ms] Http1AsyncReceiver(SocketTube(1)) Forwarding 71 bytes to delegate jdk.internal.net.http.Http1Response$HeadersReader@7ce1744a [2025-02-06T06:04:07.385Z] DEBUG: [pool-1-thread-2] [1s 84ms] Http1Response(id=1, PlainHttpConnection(SocketTube(1))) Sending 71/71 bytes to header parser [2025-02-06T06:04:07.385Z] DEBUG: [pool-1-thread-2] [1s 98ms] Http1Response(id=1, PlainHttpConnection(SocketTube(1))) Parsing headers completed. bytes=71 [2025-02-06T06:04:07.385Z] DEBUG: [pool-1-thread-2] [1s 99ms] Http1AsyncReceiver(SocketTube(1)) Unsubscribed jdk.internal.net.http.Http1Response$HeadersReader@7ce1744a [2025-02-06T06:04:07.385Z] DEBUG: [pool-1-thread-2] [1s 114ms] Http1AsyncReceiver(SocketTube(1)) Delegate done: 0 [2025-02-06T06:04:07.385Z] DEBUG: [pool-1-thread-1] [1s 115ms] Http1Exchange initiating completion of bodySentCF [2025-02-06T06:04:07.385Z] DEBUG: [pool-1-thread-1] [1s 117ms] Http1Publisher(SocketTube(1)) completed, stopping jdk.internal.net.http.common.SequentialScheduler@3921c315 [2025-02-06T06:04:07.385Z] DEBUG: [pool-1-thread-1] [1s 118ms] Http1Exchange sendBodyAsync completed successfully [2025-02-06T06:04:07.385Z] DEBUG: [pool-1-thread-1] [1s 146ms] Http1Exchange reading headers [2025-02-06T06:04:07.385Z] DEBUG: [pool-1-thread-1] [1s 147ms] Http1Response(id=1, PlainHttpConnection(SocketTube(1))) Reading Headers: (remaining: 0) READING_BODY [2025-02-06T06:04:07.385Z] DEBUG: [pool-1-thread-1] [1s 147ms] Http1Response(id=1, PlainHttpConnection(SocketTube(1))) First time around [2025-02-06T06:04:07.385Z] DEBUG: [pool-1-thread-1] [1s 147ms] Http1Response(id=1, PlainHttpConnection(SocketTube(1))) headersReader is already completed [2025-02-06T06:04:07.385Z] DEBUG: [pool-1-thread-1] [1s 149ms] Http1Response(id=1, PlainHttpConnection(SocketTube(1))) Reading Headers: creating Response object; state is now READING_BODY [2025-02-06T06:04:07.385Z] DEBUG: [pool-1-thread-1] [1s 175ms] Http1Exchange getResponseAsync completed successfully [2025-02-06T06:04:07.385Z] DEBUG: [pool-1-thread-1] [1s 186ms] Exchange Upgrading async PlainHttpConnection: HttpConnection: java.nio.channels.SocketChannel[connected local=/127.0.0.1:54984 remote=/127.0.0.1:54981] [2025-02-06T06:04:07.385Z] DEBUG: [pool-1-thread-1] [1s 225ms] Http1Response(id=1, PlainHttpConnection(SocketTube(1))) readBody: return2Cache: false [2025-02-06T06:04:07.385Z] DEBUG: [pool-1-thread-1] [1s 510ms] Http1Response(id=1, PlainHttpConnection(SocketTube(1))) Operation started: incrementing ref count for jdk.internal.net.http.HttpClientImpl@6cc3c9a3(1) [2025-02-06T06:04:07.385Z] DEBUG: [pool-1-thread-1] [1s 554ms] Http1AsyncReceiver(SocketTube(1)) Subscribed pending jdk.internal.net.http.Http1Response$BodyReader@7505b5ee/parser=jdk.internal.net.http.ResponseContent$FixedLengthBodyParser@e9b2066 queue.isEmpty: false [2025-02-06T06:04:07.385Z] DEBUG: [pool-1-thread-1] [1s 557ms] PlainHttpConnection(SocketTube(1))/ResponseContent/FixedLengthBodyParser length=0, onSubscribe: jdk.internal.net.http.Http1Response$Http1BodySubscriber [2025-02-06T06:04:07.385Z] DEBUG: [pool-1-thread-1] [1s 559ms] Http1AsyncReceiver(SocketTube(1)) cleared [2025-02-06T06:04:07.385Z] DEBUG: [pool-1-thread-1] [1s 561ms] Http1AsyncReceiver(SocketTube(1)) delegate is now jdk.internal.net.http.Http1Response$BodyReader@7505b5ee/parser=jdk.internal.net.http.ResponseContent$FixedLengthBodyParser@e9b2066, demand=9223372036854775807, canRequestMore=false, queue.isEmpty=false [2025-02-06T06:04:07.385Z] DEBUG: [pool-1-thread-1] [1s 562ms] Http1AsyncReceiver(SocketTube(1)) Got 0 bytes for delegate jdk.internal.net.http.Http1Response$BodyReader@7505b5ee/parser=jdk.internal.net.http.ResponseContent$FixedLengthBodyParser@e9b2066 [2025-02-06T06:04:07.385Z] DEBUG: [pool-1-thread-1] [1s 562ms] Http1AsyncReceiver(SocketTube(1)) downstream subscription demand is 9223372036854775807 [2025-02-06T06:04:07.385Z] DEBUG: [pool-1-thread-1] [1s 577ms] Http1AsyncReceiver(SocketTube(1)) Forwarding 0 bytes to delegate jdk.internal.net.http.Http1Response$BodyReader@7505b5ee/parser=jdk.internal.net.http.ResponseContent$FixedLengthBodyParser@e9b2066 [2025-02-06T06:04:07.385Z] DEBUG: [pool-1-thread-1] [1s 578ms] Http1AsyncReceiver(SocketTube(1)) Delegate done: 0 [2025-02-06T06:04:07.385Z] DEBUG: [pool-1-thread-1] [1s 579ms] Http1AsyncReceiver(SocketTube(1)) Got 0 bytes for delegate jdk.internal.net.http.Http1Response$BodyReader@7505b5ee/parser=jdk.internal.net.http.ResponseContent$FixedLengthBodyParser@e9b2066 [2025-02-06T06:04:07.385Z] DEBUG: [pool-1-thread-1] [1s 584ms] Http1AsyncReceiver(SocketTube(1)) downstream subscription demand is 9223372036854775807 [2025-02-06T06:04:07.385Z] DEBUG: [pool-1-thread-1] [1s 584ms] Http1AsyncReceiver(SocketTube(1)) Forwarding 0 bytes to delegate jdk.internal.net.http.Http1Response$BodyReader@7505b5ee/parser=jdk.internal.net.http.ResponseContent$FixedLengthBodyParser@e9b2066 [2025-02-06T06:04:07.385Z] DEBUG: [pool-1-thread-1] [1s 585ms] Http1AsyncReceiver(SocketTube(1)) Delegate done: 0 [2025-02-06T06:04:07.385Z] DEBUG: [pool-1-thread-1] [1s 588ms] Http1Response(id=1, PlainHttpConnection(SocketTube(1))) Finished reading body: READING_BODY [2025-02-06T06:04:07.385Z] DEBUG: [pool-1-thread-1] [1s 589ms] Http1Response(id=1, PlainHttpConnection(SocketTube(1))) Operation finished: decrementing ref count for jdk.internal.net.http.HttpClientImpl@6cc3c9a3(1) [2025-02-06T06:04:07.385Z] DEBUG: [pool-1-thread-1] [1s 770ms] Exchange Ignored body [2025-02-06T06:04:07.385Z] DEBUG: [pool-1-thread-1] [2s 524ms] Http2Connection(SocketTube(1)):WindowUpdateSender(stream: 0) maxFrameSize=16384, initWindowSize=33554432, limit=16777216 [2025-02-06T06:04:07.385Z] DEBUG: [pool-1-thread-1] [2s 570ms] Http2Connection(SocketTube(1)):WindowUpdateSender(stream: ?) maxFrameSize=16384, initWindowSize=16777216, limit=8388608 [2025-02-06T06:04:07.385Z] DEBUG: [pool-1-thread-1] [2s 572ms] Http2Connection(SocketTube(1))/Stream(1) Stream 1 registered (cancelled: false, registerIfCancelled: true) [2025-02-06T06:04:07.385Z] DEBUG: [pool-1-thread-1] [2s 572ms] Http2Connection(SocketTube(1))/Stream(1) requestSent: streamid=1 but response not received [2025-02-06T06:04:07.385Z] DEBUG: [pool-1-thread-1] [2s 573ms] SocketTube(1) connecting flows [2025-02-06T06:04:07.385Z] DEBUG: [pool-1-thread-1] [2s 573ms] SocketTube(1) read publisher got subscriber [2025-02-06T06:04:07.385Z] DEBUG: [pool-1-thread-1] [2s 573ms] SocketTube(1) registering subscribe event [2025-02-06T06:04:07.385Z] DEBUG: [pool-1-thread-1] [2s 573ms] SocketTube(1) leaving read.subscribe: Reading: [ops=1, demand=0, stopped=false], Writing: [ops=0, demand=1] [2025-02-06T06:04:07.385Z] DEBUG: [pool-1-thread-1] [2s 574ms] SocketTube(1) subscribed for writing [2025-02-06T06:04:07.385Z] DEBUG: [pool-1-thread-1] [2s 574ms] SocketTube(1) write: resetting demand to 0 [2025-02-06T06:04:07.385Z] DEBUG: [pool-1-thread-1] [2s 575ms] SocketTube(1) write: registering startSubscription event [2025-02-06T06:04:07.385Z] DEBUG: [HttpClient-1-SelectorManager] [2s 580ms] SocketTube(1) subscribe event raised [2025-02-06T06:04:07.385Z] DEBUG: [HttpClient-1-SelectorManager] [2s 580ms] SocketTube(1) handling pending subscription for jdk.internal.net.http.Http2Connection$Http2TubeSubscriber@567faba8 [2025-02-06T06:04:07.385Z] DEBUG: [HttpClient-1-SelectorManager] [2s 580ms] Http1AsyncReceiver(SocketTube(1)) Http1TubeSubscriber: dropSubscription [2025-02-06T06:04:07.385Z] DEBUG: [HttpClient-1-SelectorManager] [2s 580ms] SocketTube(1) read demand reset to 0 [2025-02-06T06:04:07.385Z] DEBUG: [HttpClient-1-SelectorManager] [2s 580ms] SocketTube(1) calling onSubscribe [2025-02-06T06:04:07.385Z] DEBUG: [HttpClient-1-SelectorManager] [2s 581ms] Http2Connection(SocketTube(1)) onSubscribe: requesting Long.MAX_VALUE for reading [2025-02-06T06:04:07.385Z] DEBUG: [HttpClient-1-SelectorManager] [2s 581ms] SocketTube(1) got some demand for reading [2025-02-06T06:04:07.385Z] DEBUG: [HttpClient-1-SelectorManager] [2s 581ms] SocketTube(1) resuming read event [2025-02-06T06:04:07.385Z] DEBUG: [HttpClient-1-SelectorManager] [2s 581ms] SelectorAttachment Registering jdk.internal.net.http.SocketTube$InternalReadPublisher$ReadEvent@3854c37e for 1 (false) [2025-02-06T06:04:07.385Z] DEBUG: [HttpClient-1-SelectorManager] [2s 581ms] SocketTube(1) leaving request(9223372036854775807): Reading: [ops=1, demand=9223372036854775807, stopped=false], Writing: [ops=0, demand=0] [2025-02-06T06:04:07.385Z] DEBUG: [HttpClient-1-SelectorManager] [2s 582ms] SocketTube(1) onSubscribe called [2025-02-06T06:04:07.385Z] DEBUG: [HttpClient-1-SelectorManager] [2s 582ms] SocketTube(1) pending subscriber subscribed [2025-02-06T06:04:07.385Z] DEBUG: [HttpClient-1-SelectorManager] [2s 582ms] SocketTube(1) write: starting subscription [2025-02-06T06:04:07.385Z] DEBUG: [HttpClient-1-SelectorManager] [2s 582ms] SocketTube(1) write: offloading requestMore [2025-02-06T06:04:07.385Z] DEBUG: [pool-1-thread-2] [2s 589ms] SocketTube(1) write: requesting more... [2025-02-06T06:04:07.385Z] DEBUG: [pool-1-thread-2] [2s 591ms] PlainHttpConnection(SocketTube(1)) HttpPublisher: got request of 1 from SocketTube(1) [2025-02-06T06:04:07.385Z] DEBUG: [pool-1-thread-2] [2s 591ms] SocketTube(1) leaving requestMore: Reading: [ops=1, demand=9223372036854775807, stopped=false], Writing: [ops=0, demand=1] [2025-02-06T06:04:07.385Z] DEBUG: [pool-1-thread-1] [2s 677ms] PlainHttpConnection(SocketTube(1)) added 69 bytes in the priority write queue [2025-02-06T06:04:07.385Z] DEBUG: [pool-1-thread-1] [2s 745ms] PlainHttpConnection(SocketTube(1)) signalling the publisher of the write queue [2025-02-06T06:04:07.385Z] DEBUG: [pool-1-thread-1] [2s 823ms] PlainHttpConnection(SocketTube(1)) HttpPublisher: sending 69 bytes (1 buffers) to SocketTube(1) [2025-02-06T06:04:07.385Z] DEBUG: [pool-1-thread-1] [2s 823ms] SocketTube(1) trying to write: 69 [2025-02-06T06:04:07.385Z] DEBUG: [pool-1-thread-1] [2s 824ms] SocketTube(1) wrote: 69 [2025-02-06T06:04:07.385Z] DEBUG: [pool-1-thread-1] [2s 824ms] SocketTube(1) write: requesting more... [2025-02-06T06:04:07.385Z] DEBUG: [pool-1-thread-1] [2s 824ms] PlainHttpConnection(SocketTube(1)) HttpPublisher: got request of 1 from SocketTube(1) [2025-02-06T06:04:07.385Z] DEBUG: [pool-1-thread-1] [2s 824ms] SocketTube(1) leaving requestMore: Reading: [ops=1, demand=9223372036854775807, stopped=false], Writing: [ops=0, demand=1] [2025-02-06T06:04:07.385Z] DEBUG: [pool-1-thread-1] [2s 824ms] SocketTube(1) leaving w.onNext Reading: [ops=1, demand=9223372036854775807, stopped=false], Writing: [ops=0, demand=1] [2025-02-06T06:04:07.385Z] DEBUG: [pool-1-thread-1] [2s 825ms] Http2Connection(SocketTube(1)):WindowUpdateSender(stream: 0) sending window update: 33488897 [2025-02-06T06:04:07.385Z] DEBUG: [pool-1-thread-1] [2s 825ms] PlainHttpConnection(SocketTube(1)) added 13 bytes in the priority write queue [2025-02-06T06:04:07.385Z] DEBUG: [pool-1-thread-1] [2s 825ms] PlainHttpConnection(SocketTube(1)) signalling the publisher of the write queue [2025-02-06T06:04:07.385Z] DEBUG: [pool-1-thread-1] [2s 826ms] PlainHttpConnection(SocketTube(1)) HttpPublisher: sending 13 bytes (1 buffers) to SocketTube(1) [2025-02-06T06:04:07.385Z] DEBUG: [pool-1-thread-1] [2s 826ms] SocketTube(1) trying to write: 13 [2025-02-06T06:04:07.385Z] DEBUG: [pool-1-thread-1] [2s 826ms] SocketTube(1) wrote: 13 [2025-02-06T06:04:07.385Z] DEBUG: [pool-1-thread-1] [2s 827ms] SocketTube(1) write: requesting more... [2025-02-06T06:04:07.385Z] DEBUG: [pool-1-thread-1] [2s 827ms] PlainHttpConnection(SocketTube(1)) HttpPublisher: got request of 1 from SocketTube(1) [2025-02-06T06:04:07.385Z] DEBUG: [pool-1-thread-1] [2s 827ms] SocketTube(1) leaving requestMore: Reading: [ops=1, demand=9223372036854775807, stopped=false], Writing: [ops=0, demand=1] [2025-02-06T06:04:07.385Z] DEBUG: [pool-1-thread-1] [2s 827ms] SocketTube(1) leaving w.onNext Reading: [ops=1, demand=9223372036854775807, stopped=false], Writing: [ops=0, demand=1] [2025-02-06T06:04:07.385Z] DEBUG: [pool-1-thread-1] [2s 828ms] Http2Connection(SocketTube(1)) Triggering processing of buffered data after sending connection preface [2025-02-06T06:04:07.385Z] DEBUG: [Test-server-pool] [2s 834ms] FramesDecoder decodes: 9 [2025-02-06T06:04:07.385Z] DEBUG: [Test-server-pool] [2s 834ms] FramesDecoder Tail size is now: 0, current= [2025-02-06T06:04:07.385Z] DEBUG: [Test-server-pool] [2s 835ms] FramesDecoder Not enough data to parse frame body, needs: 36, has: 0 [2025-02-06T06:04:07.385Z] DEBUG: [Test-server-pool] [2s 835ms] FramesDecoder decodes: 36 [2025-02-06T06:04:07.385Z] DEBUG: [Test-server-pool] [2s 835ms] FramesDecoder Tail size is now: 0, current= [2025-02-06T06:04:07.385Z] DEBUG: [Test-server-pool] [2s 835ms] FramesDecoder Got frame: SETTINGS: length=36, streamid=0, flags=0 Settings: HEADER_TABLE_SIZE=16384 ENABLE_PUSH=1 MAX_CONCURRENT_STREAMS=100 INITIAL_WINDOW_SIZE=16777216 MAX_FRAME_SIZE=16384 MAX_HEADER_LIST_SIZE=393216 [2025-02-06T06:04:07.385Z] TestServer: GET /http2/fixed/y [2025-02-06T06:04:07.385Z] Server: creating input stream for stream 1 [2025-02-06T06:04:07.385Z] DEBUG: [readLoop] [3s 2ms] FramesDecoder decodes: 9 [2025-02-06T06:04:07.385Z] DEBUG: [readLoop] [3s 3ms] FramesDecoder Tail size is now: 0, current= [2025-02-06T06:04:07.385Z] DEBUG: [readLoop] [3s 3ms] FramesDecoder Not enough data to parse frame body, needs: 36, has: 0 [2025-02-06T06:04:07.385Z] DEBUG: [readLoop] [3s 32ms] FramesDecoder decodes: 36 [2025-02-06T06:04:07.385Z] DEBUG: [readLoop] [3s 33ms] FramesDecoder Tail size is now: 0, current= [2025-02-06T06:04:07.385Z] DEBUG: [readLoop] [3s 33ms] FramesDecoder Got frame: SETTINGS: length=36, streamid=0, flags=0 Settings: HEADER_TABLE_SIZE=16384 ENABLE_PUSH=1 MAX_CONCURRENT_STREAMS=100 INITIAL_WINDOW_SIZE=16777216 MAX_FRAME_SIZE=16384 MAX_HEADER_LIST_SIZE=393216 [2025-02-06T06:04:07.385Z] DEBUG: [readLoop] [3s 33ms] FramesDecoder decodes: 9 [2025-02-06T06:04:07.385Z] DEBUG: [readLoop] [3s 33ms] FramesDecoder Tail size is now: 0, current= [2025-02-06T06:04:07.385Z] DEBUG: [readLoop] [3s 34ms] FramesDecoder Not enough data to parse frame body, needs: 4, has: 0 [2025-02-06T06:04:07.385Z] DEBUG: [readLoop] [3s 34ms] FramesDecoder decodes: 4 [2025-02-06T06:04:07.385Z] DEBUG: [readLoop] [3s 34ms] FramesDecoder Tail size is now: 0, current= [2025-02-06T06:04:07.385Z] DEBUG: [readLoop] [3s 34ms] FramesDecoder Got frame: WINDOW_UPDATE: length=4, streamid=0, flags=0 WindowUpdate: 33488897 [2025-02-06T06:04:07.385Z] Using handler for: /http2/fixed [2025-02-06T06:04:07.385Z] DEBUG: [pool-1-thread-1] [3s 97ms] Http2Connection(SocketTube(1)) onNext: got 0 bytes in 1 buffers [2025-02-06T06:04:07.386Z] DEBUG: [pool-1-thread-1] [3s 115ms] Http2Connection(SocketTube(1)) sending 0 to Http2Connection.asyncReceive [2025-02-06T06:04:07.386Z] DEBUG: [pool-1-thread-1] [3s 115ms] Http1AsyncReceiver(SocketTube(1)) stopping [2025-02-06T06:04:07.386Z] DEBUG: [pool-1-thread-1] [3s 116ms] Http1AsyncReceiver(SocketTube(1)) Flushing 0 bytes from queue into initial buffer (remaining=0, free=0) [2025-02-06T06:04:07.386Z] TestServer: [5 s, 787 ms, 151818 ns] Pushing promise: http://127.0.0.1:54981/http2/fixed/y/before/promise-1 [2025-02-06T06:04:07.386Z] DEBUG: [HttpClient-1-SelectorManager] [3s 150ms] SelectorAttachment Registering jdk.internal.net.http.SocketTube$InternalReadPublisher$ReadEvent@3854c37e for 0 (false) [2025-02-06T06:04:07.386Z] DEBUG: [HttpClient-1-SelectorManager] [3s 150ms] SocketTube(1) read bytes: 48 [2025-02-06T06:04:07.386Z] DEBUG: [HttpClient-1-SelectorManager] [3s 151ms] Http2Connection(SocketTube(1)) onNext: got 48 bytes in 1 buffers [2025-02-06T06:04:07.386Z] DEBUG: [HttpClient-1-SelectorManager] [3s 151ms] SocketTube(1) resuming read event [2025-02-06T06:04:07.386Z] DEBUG: [HttpClient-1-SelectorManager] [3s 151ms] SelectorAttachment Registering jdk.internal.net.http.SocketTube$InternalReadPublisher$ReadEvent@3854c37e for 1 (false) [2025-02-06T06:04:07.386Z] DEBUG: [HttpClient-1-SelectorManager] [3s 151ms] SocketTube(1) leaving read() loop after onNext: Reading: [ops=1, demand=9223372036854775806, stopped=false], Writing: [ops=0, demand=1] [2025-02-06T06:04:07.386Z] Sent response headers 200 [2025-02-06T06:04:07.386Z] TestServer: [5 s, 820 ms, 145907 ns] Pushing promise: http://127.0.0.1:54981/http2/fixed/y/after/promise-2 [2025-02-06T06:04:07.386Z] TestServer: [5 s, 821 ms, 833519 ns] Pushing promise: http://127.0.0.1:54981/http2/fixed/y/after/promise-3 [2025-02-06T06:04:07.386Z] DEBUG: [HttpClient-1-SelectorManager] [3s 208ms] SelectorAttachment Registering jdk.internal.net.http.SocketTube$InternalReadPublisher$ReadEvent@3854c37e for 0 (false) [2025-02-06T06:04:07.386Z] DEBUG: [HttpClient-1-SelectorManager] [3s 209ms] SocketTube(1) read bytes: 153 [2025-02-06T06:04:07.386Z] DEBUG: [HttpClient-1-SelectorManager] [3s 209ms] Http2Connection(SocketTube(1)) onNext: got 153 bytes in 1 buffers [2025-02-06T06:04:07.386Z] DEBUG: [HttpClient-1-SelectorManager] [3s 209ms] SocketTube(1) resuming read event [2025-02-06T06:04:07.386Z] DEBUG: [HttpClient-1-SelectorManager] [3s 209ms] SelectorAttachment Registering jdk.internal.net.http.SocketTube$InternalReadPublisher$ReadEvent@3854c37e for 1 (false) [2025-02-06T06:04:07.386Z] DEBUG: [HttpClient-1-SelectorManager] [3s 210ms] SocketTube(1) leaving read() loop after onNext: Reading: [ops=1, demand=9223372036854775805, stopped=false], Writing: [ops=0, demand=1] [2025-02-06T06:04:07.386Z] DEBUG: [pool-1-thread-1] [3s 213ms] Http1AsyncReceiver(SocketTube(1)) Initial buffer now has 0 pos=0 limit=0 [2025-02-06T06:04:07.386Z] DEBUG: [pool-1-thread-1] [3s 217ms] Http2Connection(SocketTube(1)) H2 Received EMPTY_TRIGGER [2025-02-06T06:04:07.386Z] DEBUG: [pool-1-thread-1] [3s 218ms] Http2Connection(SocketTube(1)) H2 processed buffered data [2025-02-06T06:04:07.386Z] DEBUG: [pool-1-thread-1] [3s 219ms] Http2Connection(SocketTube(1)) sending 48 to Http2Connection.asyncReceive [2025-02-06T06:04:07.386Z] DEBUG: [pool-1-thread-1] [3s 221ms] Http2Connection(SocketTube(1)) H2 Receiving(1): 48 [2025-02-06T06:04:07.386Z] DEBUG: [pool-1-thread-1] [3s 222ms] Http2Connection(SocketTube(1)) Processing 48 [2025-02-06T06:04:07.386Z] DEBUG: [pool-1-thread-1] [3s 222ms] FramesDecoder decodes: 48 [2025-02-06T06:04:07.386Z] DEBUG: [pool-1-thread-1] [3s 222ms] FramesDecoder Tail size is now: 0, current= [2025-02-06T06:04:07.386Z] DEBUG: [pool-1-thread-1] [3s 222ms] FramesDecoder Got frame: SETTINGS: length=30, streamid=0, flags=0 Settings: HEADER_TABLE_SIZE=4096 ENABLE_PUSH=1 MAX_CONCURRENT_STREAMS=2147483647 INITIAL_WINDOW_SIZE=65535 MAX_FRAME_SIZE=16384 [2025-02-06T06:04:07.386Z] DEBUG: [pool-1-thread-1] [3s 224ms] PlainHttpConnection(SocketTube(1)) added 9 bytes to the write queue [2025-02-06T06:04:07.386Z] DEBUG: [pool-1-thread-1] [3s 240ms] PlainHttpConnection(SocketTube(1)) signalling the publisher of the write queue [2025-02-06T06:04:07.386Z] DEBUG: [pool-1-thread-1] [3s 241ms] PlainHttpConnection(SocketTube(1)) HttpPublisher: sending 9 bytes (1 buffers) to SocketTube(1) [2025-02-06T06:04:07.386Z] DEBUG: [pool-1-thread-1] [3s 241ms] SocketTube(1) trying to write: 9 [2025-02-06T06:04:07.386Z] DEBUG: [pool-1-thread-1] [3s 241ms] SocketTube(1) wrote: 9 [2025-02-06T06:04:07.386Z] DEBUG: [HttpClient-1-SelectorManager] [3s 243ms] SelectorAttachment Registering jdk.internal.net.http.SocketTube$InternalReadPublisher$ReadEvent@3854c37e for 0 (false) [2025-02-06T06:04:07.386Z] DEBUG: [HttpClient-1-SelectorManager] [3s 244ms] SocketTube(1) read bytes: 78 [2025-02-06T06:04:07.386Z] DEBUG: [HttpClient-1-SelectorManager] [3s 244ms] Http2Connection(SocketTube(1)) onNext: got 78 bytes in 1 buffers [2025-02-06T06:04:07.386Z] DEBUG: [HttpClient-1-SelectorManager] [3s 244ms] SocketTube(1) resuming read event [2025-02-06T06:04:07.386Z] DEBUG: [HttpClient-1-SelectorManager] [3s 245ms] SelectorAttachment Registering jdk.internal.net.http.SocketTube$InternalReadPublisher$ReadEvent@3854c37e for 1 (false) [2025-02-06T06:04:07.386Z] DEBUG: [HttpClient-1-SelectorManager] [3s 245ms] SocketTube(1) leaving read() loop after onNext: Reading: [ops=1, demand=9223372036854775804, stopped=false], Writing: [ops=0, demand=1] [2025-02-06T06:04:07.386Z] DEBUG: [pool-1-thread-1] [3s 242ms] SocketTube(1) write: requesting more... [2025-02-06T06:04:07.386Z] DEBUG: [pool-1-thread-1] [3s 245ms] PlainHttpConnection(SocketTube(1)) HttpPublisher: got request of 1 from SocketTube(1) [2025-02-06T06:04:07.386Z] DEBUG: [pool-1-thread-1] [3s 245ms] SocketTube(1) leaving requestMore: Reading: [ops=1, demand=9223372036854775804, stopped=false], Writing: [ops=0, demand=1] [2025-02-06T06:04:07.386Z] DEBUG: [pool-1-thread-1] [3s 246ms] SocketTube(1) leaving w.onNext Reading: [ops=1, demand=9223372036854775804, stopped=false], Writing: [ops=0, demand=1] [2025-02-06T06:04:07.386Z] DEBUG: [readLoop] [3s 244ms] FramesDecoder decodes: 9 [2025-02-06T06:04:07.386Z] DEBUG: [readLoop] [3s 258ms] FramesDecoder Tail size is now: 0, current= [2025-02-06T06:04:07.386Z] DEBUG: [readLoop] [3s 259ms] FramesDecoder Got frame: SETTINGS: length=0, streamid=0, flags=ACK Settings: [2025-02-06T06:04:07.386Z] DEBUG: [readLoop] [3s 259ms] FramesDecoder decodes: 0 [2025-02-06T06:04:07.386Z] DEBUG: [readLoop] [3s 259ms] FramesDecoder Tail size is now: 0, current= [2025-02-06T06:04:07.386Z] DEBUG: [HttpClient-1-SelectorManager] [3s 279ms] SelectorAttachment Registering jdk.internal.net.http.SocketTube$InternalReadPublisher$ReadEvent@3854c37e for 0 (false) [2025-02-06T06:04:07.386Z] DEBUG: [HttpClient-1-SelectorManager] [3s 280ms] SocketTube(1) read bytes: 271 [2025-02-06T06:04:07.386Z] DEBUG: [HttpClient-1-SelectorManager] [3s 280ms] Http2Connection(SocketTube(1)) onNext: got 271 bytes in 1 buffers [2025-02-06T06:04:07.386Z] DEBUG: [HttpClient-1-SelectorManager] [3s 280ms] SocketTube(1) resuming read event [2025-02-06T06:04:07.386Z] DEBUG: [HttpClient-1-SelectorManager] [3s 281ms] SelectorAttachment Registering jdk.internal.net.http.SocketTube$InternalReadPublisher$ReadEvent@3854c37e for 1 (false) [2025-02-06T06:04:07.386Z] DEBUG: [HttpClient-1-SelectorManager] [3s 281ms] SocketTube(1) leaving read() loop after onNext: Reading: [ops=1, demand=9223372036854775803, stopped=false], Writing: [ops=0, demand=1] [2025-02-06T06:04:07.386Z] DEBUG: [pool-1-thread-1] [3s 329ms] FramesDecoder Got frame: SETTINGS: length=0, streamid=0, flags=ACK Settings: [2025-02-06T06:04:07.386Z] DEBUG: [pool-1-thread-1] [3s 343ms] Http2Connection(SocketTube(1)) H2 processed(1) [2025-02-06T06:04:07.386Z] DEBUG: [pool-1-thread-1] [3s 343ms] Http2Connection(SocketTube(1)) sending 153 to Http2Connection.asyncReceive [2025-02-06T06:04:07.386Z] DEBUG: [pool-1-thread-1] [3s 344ms] Http2Connection(SocketTube(1)) H2 Receiving(2): 153 [2025-02-06T06:04:07.386Z] DEBUG: [pool-1-thread-1] [3s 344ms] Http2Connection(SocketTube(1)) Processing 153 [2025-02-06T06:04:07.386Z] DEBUG: [pool-1-thread-1] [3s 344ms] FramesDecoder decodes: 153 [2025-02-06T06:04:07.386Z] DEBUG: [pool-1-thread-1] [3s 344ms] FramesDecoder Tail size is now: 0, current= [2025-02-06T06:04:07.386Z] DEBUG: [pool-1-thread-1] [3s 582ms] FramesDecoder Got frame: PUSH_PROMISE: length=51, streamid=1, flags=END_HEADERS promisedStreamid: 2 headerLength: 47 [2025-02-06T06:04:07.386Z] DEBUG: [pool-1-thread-1] [3s 591ms] Http2Connection(SocketTube(1)):WindowUpdateSender(stream: ?) maxFrameSize=16384, initWindowSize=16777216, limit=8388608 [2025-02-06T06:04:07.386Z] DEBUG: [pool-1-thread-1] [3s 591ms] Http2Connection(SocketTube(1))/Stream(2) Stream 2 registered (cancelled: false, registerIfCancelled: true) [2025-02-06T06:04:07.386Z] DEBUG: [pool-1-thread-1] [3s 723ms] Http2Connection(SocketTube(1))/Stream(2) requestSent: streamid=2 but response not received [2025-02-06T06:04:07.386Z] DEBUG: [pool-1-thread-1] [3s 725ms] FramesDecoder Got frame: HEADERS: length=6, streamid=1, flags=END_HEADERS [2025-02-06T06:04:07.386Z] DEBUG: [pool-1-thread-1] [3s 760ms] Http2Connection(SocketTube(1))/Stream(1) incoming: HEADERS: length=6, streamid=1, flags=END_HEADERS [2025-02-06T06:04:07.386Z] DEBUG: [pool-1-thread-1] [3s 778ms] Http2Connection(SocketTube(1))/Stream(1) Response builder cleared, ready to receive new headers. [2025-02-06T06:04:07.386Z] DEBUG: [pool-1-thread-1] [3s 778ms] Http2Connection(SocketTube(1))/Stream(1) Adding completed responseCF(0) with response headers [2025-02-06T06:04:07.386Z] DEBUG: [pool-1-thread-1] [3s 778ms] FramesDecoder Got frame: DATA: length=12, streamid=1, flags=0 [2025-02-06T06:04:07.386Z] DEBUG: [pool-1-thread-1] [3s 779ms] Http2Connection(SocketTube(1))/Stream(1) incoming: DATA: length=12, streamid=1, flags=0 [2025-02-06T06:04:07.386Z] DEBUG: [pool-1-thread-1] [3s 779ms] FramesDecoder Got frame: PUSH_PROMISE: length=48, streamid=1, flags=END_HEADERS promisedStreamid: 4 headerLength: 44 [2025-02-06T06:04:07.386Z] DEBUG: [pool-1-thread-1] [3s 781ms] Http2Connection(SocketTube(1)):WindowUpdateSender(stream: ?) maxFrameSize=16384, initWindowSize=16777216, limit=8388608 [2025-02-06T06:04:07.386Z] DEBUG: [pool-1-thread-1] [3s 781ms] Http2Connection(SocketTube(1))/Stream(4) Stream 4 registered (cancelled: false, registerIfCancelled: true) [2025-02-06T06:04:07.386Z] DEBUG: [pool-1-thread-1] [3s 781ms] Http2Connection(SocketTube(1))/Stream(4) requestSent: streamid=4 but response not received [2025-02-06T06:04:07.386Z] DEBUG: [pool-1-thread-1] [3s 782ms] Http2Connection(SocketTube(1)) H2 processed(2) [2025-02-06T06:04:07.386Z] DEBUG: [pool-1-thread-1] [3s 832ms] Http2Connection(SocketTube(1)) sending 78 to Http2Connection.asyncReceive [2025-02-06T06:04:07.386Z] DEBUG: [pool-1-thread-1] [3s 836ms] Http2Connection(SocketTube(1)) H2 Receiving(3): 78 [2025-02-06T06:04:07.386Z] DEBUG: [pool-1-thread-1] [3s 836ms] Http2Connection(SocketTube(1)) Processing 78 [2025-02-06T06:04:07.386Z] DEBUG: [pool-1-thread-1] [3s 836ms] FramesDecoder decodes: 78 [2025-02-06T06:04:07.386Z] DEBUG: [pool-1-thread-1] [3s 836ms] FramesDecoder Tail size is now: 0, current= [2025-02-06T06:04:07.386Z] DEBUG: [pool-1-thread-1] [3s 837ms] FramesDecoder Got frame: DATA: length=12, streamid=1, flags=0 [2025-02-06T06:04:07.386Z] DEBUG: [pool-1-thread-1] [3s 837ms] Http2Connection(SocketTube(1))/Stream(1) incoming: DATA: length=12, streamid=1, flags=0 [2025-02-06T06:04:07.386Z] DEBUG: [pool-1-thread-1] [3s 837ms] FramesDecoder Got frame: PUSH_PROMISE: length=48, streamid=1, flags=END_HEADERS promisedStreamid: 6 headerLength: 44 [2025-02-06T06:04:07.386Z] DEBUG: [pool-1-thread-1] [3s 839ms] Http2Connection(SocketTube(1)):WindowUpdateSender(stream: ?) maxFrameSize=16384, initWindowSize=16777216, limit=8388608 [2025-02-06T06:04:07.386Z] DEBUG: [pool-1-thread-1] [3s 839ms] Http2Connection(SocketTube(1))/Stream(6) Stream 6 registered (cancelled: false, registerIfCancelled: true) [2025-02-06T06:04:07.386Z] DEBUG: [pool-1-thread-1] [3s 840ms] Http2Connection(SocketTube(1))/Stream(6) requestSent: streamid=6 but response not received [2025-02-06T06:04:07.386Z] DEBUG: [pool-1-thread-1] [3s 840ms] Http2Connection(SocketTube(1)) H2 processed(3) [2025-02-06T06:04:07.386Z] DEBUG: [pool-1-thread-1] [3s 840ms] Http2Connection(SocketTube(1)) sending 271 to Http2Connection.asyncReceive [2025-02-06T06:04:07.386Z] DEBUG: [pool-1-thread-1] [3s 840ms] Http2Connection(SocketTube(1)) H2 Receiving(4): 271 [2025-02-06T06:04:07.386Z] DEBUG: [pool-1-thread-1] [3s 841ms] Http2Connection(SocketTube(1)) Processing 271 [2025-02-06T06:04:07.386Z] DEBUG: [pool-1-thread-1] [3s 841ms] FramesDecoder decodes: 271 [2025-02-06T06:04:07.386Z] DEBUG: [pool-1-thread-1] [3s 841ms] FramesDecoder Tail size is now: 0, current= [2025-02-06T06:04:07.386Z] DEBUG: [pool-1-thread-1] [3s 841ms] FramesDecoder Got frame: DATA: length=12, streamid=1, flags=0 [2025-02-06T06:04:07.386Z] DEBUG: [pool-1-thread-1] [3s 841ms] Http2Connection(SocketTube(1))/Stream(1) incoming: DATA: length=12, streamid=1, flags=0 [2025-02-06T06:04:07.386Z] DEBUG: [pool-1-thread-1] [3s 842ms] FramesDecoder Got frame: DATA: length=0, streamid=1, flags=END_STREAM [2025-02-06T06:04:07.386Z] DEBUG: [pool-1-thread-1] [3s 842ms] Http2Connection(SocketTube(1))/Stream(1) incoming: DATA: length=0, streamid=1, flags=END_STREAM [2025-02-06T06:04:07.386Z] DEBUG: [pool-1-thread-1] [3s 842ms] FramesDecoder Got frame: HEADERS: length=1, streamid=2, flags=END_HEADERS [2025-02-06T06:04:07.386Z] DEBUG: [pool-1-thread-1] [3s 843ms] Http2Connection(SocketTube(1))/Stream(2) incoming: HEADERS: length=1, streamid=2, flags=END_HEADERS [2025-02-06T06:04:07.386Z] DEBUG: [pool-1-thread-1] [3s 843ms] Http2Connection(SocketTube(1))/Stream(2) Response builder cleared, ready to receive new headers. [2025-02-06T06:04:07.386Z] DEBUG: [pool-1-thread-1] [3s 864ms] Http2Connection(SocketTube(1))/Stream(2) Getting BodySubscriber for: (GET http://127.0.0.1:54981/http2/fixed/y/before/promise-1) 200 HTTP_2 Local port: 54984 [2025-02-06T06:04:07.386Z] DEBUG: [pool-1-thread-1] [3s 877ms] Http2Connection(SocketTube(1))/Stream(2) subscribing user subscriber [2025-02-06T06:04:07.386Z] DEBUG: [pool-1-thread-1] [3s 883ms] HttpResponseInputStream onSubscribe: requesting 1 [2025-02-06T06:04:07.386Z] DEBUG: [pool-1-thread-1] [3s 895ms] FramesDecoder Got frame: DATA: length=53, streamid=2, flags=0 [2025-02-06T06:04:07.386Z] DEBUG: [pool-1-thread-1] [3s 895ms] Http2Connection(SocketTube(1))/Stream(2) incoming: DATA: length=53, streamid=2, flags=0 [2025-02-06T06:04:07.386Z] DEBUG: [pool-1-thread-1] [3s 895ms] Http2Connection(SocketTube(1))/Stream(2) incoming: onNext(53) [2025-02-06T06:04:07.386Z] DEBUG: [pool-1-thread-1] [3s 902ms] HttpResponseInputStream next item received [2025-02-06T06:04:07.386Z] DEBUG: [pool-1-thread-1] [3s 902ms] HttpResponseInputStream item offered [2025-02-06T06:04:07.386Z] DEBUG: [pool-1-thread-1] [3s 903ms] Http2Connection(SocketTube(1)):WindowUpdateSender(stream: 0) update: 53, received: 53, limit: 16777216 [2025-02-06T06:04:07.386Z] DEBUG: [pool-1-thread-1] [3s 904ms] Http2Connection(SocketTube(1)):WindowUpdateSender(stream: 2) update: 53, received: 53, limit: 8388608 [2025-02-06T06:04:07.386Z] DEBUG: [pool-1-thread-1] [3s 904ms] FramesDecoder Got frame: DATA: length=0, streamid=2, flags=END_STREAM [2025-02-06T06:04:07.386Z] DEBUG: [pool-1-thread-1] [3s 913ms] Http2Connection(SocketTube(1))/Stream(2) incoming: DATA: length=0, streamid=2, flags=END_STREAM [2025-02-06T06:04:07.386Z] DEBUG: [pool-1-thread-1] [3s 914ms] Http2Connection(SocketTube(1))/Stream(2) incoming: onComplete [2025-02-06T06:04:07.386Z] DEBUG: [pool-1-thread-1] [3s 914ms] HttpResponseInputStream next item received [2025-02-06T06:04:07.386Z] DEBUG: [pool-1-thread-1] [3s 914ms] HttpResponseInputStream item offered [2025-02-06T06:04:07.386Z] DEBUG: [pool-1-thread-1] [3s 915ms] Http2Connection(SocketTube(1))/Stream(2) setEndStreamReceived: streamid=2 [2025-02-06T06:04:07.386Z] DEBUG: [pool-1-threa [2025-02-06T06:04:07.386Z] [2025-02-06T06:04:07.386Z] ... [2025-02-06T06:04:07.386Z] Output overflow: [2025-02-06T06:04:07.386Z] JT Harness has limited the test output to the text [2025-02-06T06:04:07.386Z] at the beginning and the end, so that you can see how the [2025-02-06T06:04:07.386Z] test began, and how it completed. [2025-02-06T06:04:07.386Z] [2025-02-06T06:04:07.386Z] If you need to see more of the output from the test, [2025-02-06T06:04:07.386Z] set the system property javatest.maxOutputSize to a higher [2025-02-06T06:04:07.386Z] value. The current value is 100000 [2025-02-06T06:04:07.386Z] ... [2025-02-06T06:04:07.386Z] [2025-02-06T06:04:07.386Z] 298, getALPN: jdk.internal.net.http.common.MinimalFuture@347e9d7e[Completed normally] (id=2694), onCompleteReceived: false, onError: null], readBuf: java.nio.HeapByteBuffer[pos=80 lim=80 cap=2048], count: 530, scheduler: stopped, status: CLOSED, handshakeState: 0, engine: NOT_HANDSHAKING [2025-02-06T06:04:07.386Z] DEBUG: [HttpClient-17-SelectorManager] [16s 828ms] SocketTube(18) Stopping read scheduler [2025-02-06T06:04:07.386Z] DEBUG: [HttpClient-13-SelectorManager] [16s 827ms] SocketTube(14) leaving w.onNext Reading: [ops=0, demand=1, stopped=true], Writing: [ops=0, demand=0] [2025-02-06T06:04:07.386Z] DEBUG: [HttpClient-13-SelectorManager] [16s 828ms] SSL Writer(SocketTube(14)) upstreamWindowUpdate, downstreamQueueSize:0, upstreamWindow:1 [2025-02-06T06:04:07.386Z] DEBUG: [HttpClient-13-SelectorManager] [16s 828ms] SSL Writer(SocketTube(14)) completionAcknowledged upstreamCompleted:true, downstreamCompleted:false, closing:true [2025-02-06T06:04:07.386Z] DEBUG: [HttpClient-13-SelectorManager] [16s 828ms] SSL Writer(SocketTube(14)) pushScheduler is stopped! [2025-02-06T06:04:07.386Z] DEBUG: [HttpClient-13-SelectorManager] [16s 828ms] Http2Connection(SSLTube(SocketTube(14))) Shutting down h2c (closed=true): java.io.EOFException: HTTP/2 client stopped [2025-02-06T06:04:07.386Z] DEBUG: [HttpClient-5-SelectorManager] [16s 827ms] SSL Reader(SocketTube(6)) onError: java.net.SocketException: Connection reset [2025-02-06T06:04:07.386Z] DEBUG: [HttpClient-5-SelectorManager] [16s 828ms] SSL Reader(SocketTube(6)) error java.net.SocketException: Connection reset [2025-02-06T06:04:07.386Z] DEBUG: [HttpClient-3-SelectorManager] [16s 827ms] SocketTube(3) leaving read() loop with no demand Reading: [ops=0, demand=0, stopped=false], Writing: [ops=0, demand=1] [2025-02-06T06:04:07.386Z] java.net.SocketException: Connection reset [2025-02-06T06:04:07.386Z] at java.base/sun.nio.ch.SocketChannelImpl.throwConnectionReset(SocketChannelImpl.java:394) [2025-02-06T06:04:07.386Z] at java.base/sun.nio.ch.SocketChannelImpl.read(SocketChannelImpl.java:426) [2025-02-06T06:04:07.386Z] at java.net.http/jdk.internal.net.http.SocketTube.readAvailable(SocketTube.java:1170) [2025-02-06T06:04:07.386Z] at java.net.http/jdk.internal.net.http.SocketTube$InternalReadPublisher$InternalReadSubscription.read(SocketTube.java:833) [2025-02-06T06:04:07.386Z] at java.net.http/jdk.internal.net.http.SocketTube$SocketFlowTask.run(SocketTube.java:181) [2025-02-06T06:04:07.386Z] at java.net.http/jdk.internal.net.http.common.SequentialScheduler$SchedulableTask.run(SequentialScheduler.java:230) [2025-02-06T06:04:07.386Z] at java.net.http/jdk.internal.net.http.common.SequentialScheduler.runOrSchedule(SequentialScheduler.java:303) [2025-02-06T06:04:07.387Z] at java.net.http/jdk.internal.net.http.common.SequentialScheduler.runOrSchedule(SequentialScheduler.java:256) [2025-02-06T06:04:07.387Z] at java.net.http/jdk.internal.net.http.SocketTube$InternalReadPublisher$InternalReadSubscription.signalReadable(SocketTube.java:774) [2025-02-06T06:04:07.387Z] at java.net.http/jdk.internal.net.http.SocketTube$InternalReadPublisher$ReadEvent.signalEvent(SocketTube.java:957) [2025-02-06T06:04:07.387Z] at java.net.http/jdk.internal.net.http.SocketTube$SocketFlowEvent.handle(SocketTube.java:253) [2025-02-06T06:04:07.387Z] at java.net.http/jdk.internal.net.http.HttpClientImpl$SelectorManager.handleEvent(HttpClientImpl.java:984) [2025-02-06T06:04:07.387Z] at java.net.http/jdk.internal.net.http.HttpClientImpl$SelectorManager.lambda$run$3(HttpClientImpl.java:939) [2025-02-06T06:04:07.387Z] at java.base/java.util.ArrayList.forEach(ArrayList.java:1511) [2025-02-06T06:04:07.387Z] at java.net.http/jdk.internal.net.http.HttpClientImpl$SelectorManager.run(HttpClientImpl.java:939) [2025-02-06T06:04:07.387Z] DEBUG: [HttpClient-5-SelectorManager] [16s 828ms] SSL Reader(SocketTube(6)) DownstreamPusher: forwarding error downstream: java.net.SocketException: Connection reset [2025-02-06T06:04:07.387Z] DEBUG: [pool-1-thread-1] [16s 828ms] SSL Reader(SocketTube(10)) processData: readBuf remaining:80, state: NOT_HANDSHAKING , engine handshake status:NOT_HANDSHAKING [2025-02-06T06:04:07.387Z] DEBUG: [HttpClient-5-SelectorManager] [16s 828ms] SSLTube(SocketTube(6)) SSLSubscriberWrapper[SSLTube(SocketTube(6)), delegate: DelegateWrapper[subscribedCalled: true, subscribedDone: true, completed: false, error: null]: jdk.internal.net.http.Http2Connection$Http2TubeSubscriber@1de7ba35, getALPN: jdk.internal.net.http.common.MinimalFuture@2918b08f[Completed normally] (id=648), onCompleteReceived: false, onError: java.net.SocketException: Connection reset]: onErrorImpl: java.net.SocketException: Connection reset [2025-02-06T06:04:07.387Z] DEBUG: [HttpClient-17-SelectorManager] [16s 828ms] SocketTube(18) leaving read() loop with error: Reading: [ops=0, demand=0, stopped=true], Writing: [ops=0, demand=0] [2025-02-06T06:04:07.387Z] DEBUG: [HttpClient-17-SelectorManager] [16s 828ms] SocketTube(18) Read scheduler stopped [2025-02-06T06:04:07.387Z] DEBUG: [HttpClient-9-SelectorManager] [16s 828ms] SocketTube(10) resuming read event [2025-02-06T06:04:07.387Z] DEBUG: [HttpClient-9-SelectorManager] [16s 828ms] SelectorAttachment Registering jdk.internal.net.http.SocketTube$InternalReadPublisher$ReadEvent@191ee150 for 1 (false) [2025-02-06T06:04:07.387Z] DEBUG: [HttpClient-9-SelectorManager] [16s 828ms] SocketTube(10) leaving read() loop after onNext: Reading: [ops=1, demand=0, stopped=false], Writing: [ops=0, demand=1] [2025-02-06T06:04:07.387Z] DEBUG: [HttpClient-8-SelectorManager] [16s 828ms] SelectorAttachment Registering jdk.internal.net.http.SocketTube$InternalReadPublisher$ReadEvent@7370593f for 1 (false) [2025-02-06T06:04:07.387Z] DEBUG: [HttpClient-8-SelectorManager] [16s 828ms] SocketTube(9) leaving read() loop after onNext: Reading: [ops=1, demand=0, stopped=false], Writing: [ops=0, demand=1] [2025-02-06T06:04:07.387Z] DEBUG: [pool-1-thread-3] [16s 828ms] SSL Writer(SocketTube(3)) DownstreamPusher: queue not empty, downstreamSubscription: SubscriptionBase: window = 1 cancelled = false [2025-02-06T06:04:07.387Z] DEBUG: [HttpClient-8-SelectorManager] [16s 828ms] HttpClientImpl(8) SelectorManager shutting down [2025-02-06T06:04:07.387Z] DEBUG: [pool-1-thread-3] [16s 828ms] SSL Writer(SocketTube(3)) DownstreamPusher: Pushing 40 bytes downstream [2025-02-06T06:04:07.387Z] DEBUG: [pool-1-thread-3] [16s 828ms] SocketTube(3) trying to write: 40 [2025-02-06T06:04:07.387Z] DEBUG: [pool-1-thread-2] [16s 828ms] SSL Reader(SocketTube(9)) processData: readBuf remaining:80, state: NOT_HANDSHAKING , engine handshake status:NOT_HANDSHAKING [2025-02-06T06:04:07.387Z] DEBUG: [pool-1-thread-2] [16s 829ms] SSL Reader(SocketTube(9)) Unwrapping: 80 [2025-02-06T06:04:07.387Z] DEBUG: [pool-1-thread-2] [16s 829ms] SSL Reader(SocketTube(9)) Decoded 0 bytes out of 80 into buffer of 64 remaining to decode: 40 [2025-02-06T06:04:07.387Z] DEBUG: [pool-1-thread-2] [16s 829ms] SSL Reader(SocketTube(9)) Unwrapped: result: Status = OK HandshakeStatus = NOT_HANDSHAKING [2025-02-06T06:04:07.387Z] bytesConsumed = 40 bytesProduced = 0 [2025-02-06T06:04:07.387Z] DEBUG: [pool-1-thread-2] [16s 829ms] SSL Reader(SocketTube(9)) Unwrapped: consumed: 40 [2025-02-06T06:04:07.387Z] DEBUG: [pool-1-thread-2] [16s 829ms] SSL Reader(SocketTube(9)) Unwrapping: 40 [2025-02-06T06:04:07.387Z] DEBUG: [pool-1-thread-2] [16s 829ms] SSLFlowDelegate(SocketTube(9)) doClosure(Status = CLOSED HandshakeStatus = NEED_WRAP [2025-02-06T06:04:07.387Z] bytesConsumed = 40 bytesProduced = 0): NEED_WRAP [isOutboundDone: false, isInboundDone: true] [2025-02-06T06:04:07.387Z] DEBUG: [pool-1-thread-2] [16s 829ms] SSLFlowDelegate(SocketTube(9)) doClosure: close_notify received [2025-02-06T06:04:07.387Z] DEBUG: [pool-1-thread-2] [16s 829ms] SSL Writer(SocketTube(9)) processData, writeList remaining:0, hsTriggered:true, needWrap:true [2025-02-06T06:04:07.387Z] DEBUG: [pool-1-thread-2] [16s 829ms] SSL Writer(SocketTube(9)) wrapping 0 bytes [2025-02-06T06:04:07.387Z] DEBUG: [pool-1-thread-2] [16s 829ms] SSL Writer(SocketTube(9)) SSLResult: Status = CLOSED HandshakeStatus = NOT_HANDSHAKING [2025-02-06T06:04:07.387Z] bytesConsumed = 0 bytesProduced = 40 sequenceNumber = 2 [2025-02-06T06:04:07.387Z] DEBUG: [pool-1-thread-2] [16s 829ms] SSL Writer(SocketTube(9)) CLOSED [2025-02-06T06:04:07.387Z] DEBUG: [pool-1-thread-2] [16s 829ms] SSL Writer(SocketTube(9)) OK => produced: 40 bytes into 40, not wrapped: 0 [2025-02-06T06:04:07.387Z] DEBUG: [pool-1-thread-2] [16s 829ms] SSL Writer(SocketTube(9)) wrapBuffer returned Status = CLOSED HandshakeStatus = NOT_HANDSHAKING [2025-02-06T06:04:07.387Z] bytesConsumed = 0 bytesProduced = 40 sequenceNumber = 2 [2025-02-06T06:04:07.387Z] DEBUG: [pool-1-thread-2] [16s 829ms] AsyncSSLConnection(SSLTube(SocketTube(9))) HttpPublisher: cancelled by SSLTube(SocketTube(9)) [2025-02-06T06:04:07.387Z] DEBUG: [pool-1-thread-2] [16s 829ms] SSL Writer(SocketTube(9)) Sending 40 bytes downstream [2025-02-06T06:04:07.387Z] DEBUG: [pool-1-thread-2] [16s 829ms] SSL Writer(SocketTube(9)) Adding 40 to outputQ queue [2025-02-06T06:04:07.387Z] DEBUG: [pool-1-thread-2] [16s 829ms] SSL Writer(SocketTube(9)) pushScheduler is alive [2025-02-06T06:04:07.387Z] DEBUG: [pool-1-thread-2] [16s 829ms] SSL Writer(SocketTube(9)) DownstreamPusher: queue not empty, downstreamSubscription: SubscriptionBase: window = 1 cancelled = false [2025-02-06T06:04:07.387Z] DEBUG: [pool-1-thread-3] [16s 828ms] SocketTube(3) wrote: 40 [2025-02-06T06:04:07.387Z] DEBUG: [pool-1-thread-3] [16s 829ms] SocketTube(3) write: requesting more... [2025-02-06T06:04:07.387Z] DEBUG: [HttpClient-8-SelectorManager] [16s 828ms] Http2ClientImpl stopping [2025-02-06T06:04:07.387Z] DEBUG: [HttpClient-9-SelectorManager] [16s 828ms] HttpClientImpl(9) SelectorManager shutting down [2025-02-06T06:04:07.387Z] DEBUG: [HttpClient-8-SelectorManager] [16s 829ms] AsyncSSLConnection(SSLTube(SocketTube(9))) added 34 bytes to the write queue [2025-02-06T06:04:07.387Z] DEBUG: [HttpClient-8-SelectorManager] [16s 829ms] AsyncSSLConnection(SSLTube(SocketTube(9))) signalling the publisher of the write queue [2025-02-06T06:04:07.387Z] DEBUG: [HttpClient-8-SelectorManager] [16s 829ms] AsyncSSLConnection(SSLTube(SocketTube(9))) HttpPublisher: sending 34 bytes (1 buffers) to SSLTube(SocketTube(9)) [2025-02-06T06:04:07.387Z] DEBUG: [HttpClient-8-SelectorManager] [16s 829ms] SSLTube(SocketTube(9)) sending 1 buffers to SSL flow delegate [2025-02-06T06:04:07.387Z] DEBUG: [HttpClient-8-SelectorManager] [16s 829ms] SSL Writer(SocketTube(9)) onNext [2025-02-06T06:04:07.387Z] DEBUG: [HttpClient-8-SelectorManager] [16s 829ms] SSL Writer(SocketTube(9)) added 1 (34 bytes) to the writeList [2025-02-06T06:04:07.387Z] DEBUG: [HttpClient-8-SelectorManager] [16s 829ms] Http2Connection(SSLTube(SocketTube(9))) Shutting down h2c (closed=false): java.io.EOFException: HTTP/2 client stopped [2025-02-06T06:04:07.387Z] DEBUG: [HttpClient-8-SelectorManager] [16s 829ms] Http2ClientImpl removing from the connection pool: Http2Connection(SSLTube(SocketTube(9))) [2025-02-06T06:04:07.387Z] DEBUG: [HttpClient-8-SelectorManager] [16s 829ms] Http2ClientImpl removed from the connection pool: Http2Connection(SSLTube(SocketTube(9))) [2025-02-06T06:04:07.387Z] DEBUG: [HttpClient-8-SelectorManager] [16s 829ms] PlainHttpConnection(SocketTube(9)) Closing channel: channel not registered with selector [2025-02-06T06:04:07.387Z] DEBUG: [HttpClient-5-SelectorManager] [16s 828ms] Http2Connection(SSLTube(SocketTube(6))) onError: java.net.SocketException: Connection reset [2025-02-06T06:04:07.387Z] DEBUG: [HttpClient-8-SelectorManager] [16s 829ms] SocketTube(9) signal read error: java.io.IOException: connection closed locally [2025-02-06T06:04:07.387Z] DEBUG: [HttpClient-8-SelectorManager] [16s 829ms] SocketTube(9) got read error: java.io.IOException: connection closed locally [2025-02-06T06:04:07.387Z] DEBUG: [HttpClient-5-SelectorManager] [16s 829ms] SSLTube(SocketTube(6)) subscriber completed with error: java.net.SocketException: Connection reset [2025-02-06T06:04:07.387Z] DEBUG: [pool-1-thread-1] [16s 828ms] SSL Reader(SocketTube(10)) Unwrapping: 80 [2025-02-06T06:04:07.387Z] DEBUG: [pool-1-thread-1] [16s 830ms] SSL Reader(SocketTube(10)) Decoded 0 bytes out of 80 into buffer of 64 remaining to decode: 40 [2025-02-06T06:04:07.387Z] DEBUG: [pool-1-thread-1] [16s 830ms] SSL Reader(SocketTube(10)) Unwrapped: result: Status = OK HandshakeStatus = NOT_HANDSHAKING [2025-02-06T06:04:07.387Z] bytesConsumed = 40 bytesProduced = 0 [2025-02-06T06:04:07.387Z] DEBUG: [pool-1-thread-1] [16s 830ms] SSL Reader(SocketTube(10)) Unwrapped: consumed: 40 [2025-02-06T06:04:07.387Z] DEBUG: [pool-1-thread-1] [16s 830ms] SSL Reader(SocketTube(10)) Unwrapping: 40 [2025-02-06T06:04:07.387Z] DEBUG: [pool-1-thread-1] [16s 831ms] SSLFlowDelegate(SocketTube(10)) doClosure(Status = CLOSED HandshakeStatus = NEED_WRAP [2025-02-06T06:04:07.387Z] bytesConsumed = 40 bytesProduced = 0): NEED_WRAP [isOutboundDone: false, isInboundDone: true] [2025-02-06T06:04:07.387Z] DEBUG: [pool-1-thread-1] [16s 831ms] SSLFlowDelegate(SocketTube(10)) doClosure: close_notify received [2025-02-06T06:04:07.387Z] DEBUG: [pool-1-thread-1] [16s 831ms] SSL Writer(SocketTube(10)) processData, writeList remaining:0, hsTriggered:true, needWrap:true [2025-02-06T06:04:07.387Z] DEBUG: [pool-1-thread-1] [16s 831ms] SSL Writer(SocketTube(10)) wrapping 0 bytes [2025-02-06T06:04:07.387Z] DEBUG: [pool-1-thread-1] [16s 831ms] SSL Writer(SocketTube(10)) SSLResult: Status = CLOSED HandshakeStatus = NOT_HANDSHAKING [2025-02-06T06:04:07.387Z] bytesConsumed = 0 bytesProduced = 40 sequenceNumber = 2 [2025-02-06T06:04:07.387Z] DEBUG: [pool-1-thread-1] [16s 831ms] SSL Writer(SocketTube(10)) CLOSED [2025-02-06T06:04:07.387Z] DEBUG: [pool-1-thread-1] [16s 831ms] SSL Writer(SocketTube(10)) OK => produced: 40 bytes into 40, not wrapped: 0 [2025-02-06T06:04:07.387Z] DEBUG: [pool-1-thread-1] [16s 831ms] SSL Writer(SocketTube(10)) wrapBuffer returned Status = CLOSED HandshakeStatus = NOT_HANDSHAKING [2025-02-06T06:04:07.387Z] bytesConsumed = 0 bytesProduced = 40 sequenceNumber = 2 [2025-02-06T06:04:07.387Z] DEBUG: [pool-1-thread-1] [16s 831ms] AsyncSSLConnection(SSLTube(SocketTube(10))) HttpPublisher: cancelled by SSLTube(SocketTube(10)) [2025-02-06T06:04:07.387Z] DEBUG: [pool-1-thread-1] [16s 831ms] SSL Writer(SocketTube(10)) Sending 40 bytes downstream [2025-02-06T06:04:07.387Z] DEBUG: [pool-1-thread-1] [16s 831ms] SSL Writer(SocketTube(10)) Adding 40 to outputQ queue [2025-02-06T06:04:07.387Z] DEBUG: [pool-1-thread-1] [16s 831ms] SSL Writer(SocketTube(10)) pushScheduler is alive [2025-02-06T06:04:07.387Z] DEBUG: [pool-1-thread-1] [16s 831ms] SSL Writer(SocketTube(10)) DownstreamPusher: queue not empty, downstreamSubscription: SubscriptionBase: window = 1 cancelled = false [2025-02-06T06:04:07.387Z] DEBUG: [pool-1-thread-1] [16s 831ms] SSL Writer(SocketTube(10)) DownstreamPusher: Pushing 40 bytes downstream [2025-02-06T06:04:07.387Z] DEBUG: [pool-1-thread-1] [16s 831ms] SocketTube(10) trying to write: 40 [2025-02-06T06:04:07.387Z] DEBUG: [pool-1-thread-1] [16s 831ms] SocketTube(10) wrote: 40 [2025-02-06T06:04:07.387Z] DEBUG: [pool-1-thread-1] [16s 831ms] SocketTube(10) write: requesting more... [2025-02-06T06:04:07.387Z] DEBUG: [pool-1-thread-1] [16s 831ms] SocketTube(10) leaving requestMore: Reading: [ops=1, demand=0, stopped=false], Writing: [ops=0, demand=1] [2025-02-06T06:04:07.387Z] DEBUG: [pool-1-thread-1] [16s 831ms] SocketTube(10) leaving w.onNext Reading: [ops=1, demand=0, stopped=false], Writing: [ops=0, demand=1] [2025-02-06T06:04:07.387Z] DEBUG: [pool-1-thread-1] [16s 831ms] SSL Writer(SocketTube(10)) upstreamWindowUpdate, downstreamQueueSize:0, upstreamWindow:1 [2025-02-06T06:04:07.387Z] DEBUG: [pool-1-thread-1] [16s 831ms] SSL Writer(SocketTube(10)) DownstreamPusher: queue empty, downstreamSubscription: SubscriptionBase: window = 1 cancelled = false [2025-02-06T06:04:07.387Z] DEBUG: [pool-1-thread-1] [16s 831ms] SSL Writer(SocketTube(10)) completionAcknowledged upstreamCompleted:true, downstreamCompleted:false, closing:true [2025-02-06T06:04:07.387Z] DEBUG: [pool-1-thread-1] [16s 831ms] SSL Writer(SocketTube(10)) pushScheduler is alive [2025-02-06T06:04:07.387Z] DEBUG: [pool-1-thread-1] [16s 831ms] SSL Writer(SocketTube(10)) DownstreamPusher: queue empty, downstreamSubscription: SubscriptionBase: window = 1 cancelled = false [2025-02-06T06:04:07.387Z] DEBUG: [pool-1-thread-1] [16s 831ms] SSL Writer(SocketTube(10)) calling downstreamSubscriber.onComplete() [2025-02-06T06:04:07.387Z] DEBUG: [pool-1-thread-1] [16s 831ms] SocketTube(10) write completed, 0 yet to send [2025-02-06T06:04:07.387Z] DEBUG: [pool-1-thread-1] [16s 831ms] SocketTube(10) InternalWriteSubscriber::onComplete Reading: [ops=1, demand=0, stopped=false], Writing: [ops=0, demand=1] [2025-02-06T06:04:07.387Z] DEBUG: [pool-1-thread-1] [16s 831ms] SSL Writer(SocketTube(10)) processData, writeList remaining:0, hsTriggered:false, needWrap:false [2025-02-06T06:04:07.387Z] DEBUG: [pool-1-thread-1] [16s 831ms] SSL Reader(SocketTube(10)) Unwrapped: result: Status = CLOSED HandshakeStatus = NEED_WRAP [2025-02-06T06:04:07.387Z] bytesConsumed = 40 bytesProduced = 0 [2025-02-06T06:04:07.387Z] DEBUG: [pool-1-thread-1] [16s 831ms] SSL Reader(SocketTube(10)) Unwrapped: consumed: 40 [2025-02-06T06:04:07.387Z] DEBUG: [pool-1-thread-1] [16s 831ms] SSL Reader(SocketTube(10)) requesting 1 [2025-02-06T06:04:07.387Z] DEBUG: [pool-1-thread-1] [16s 831ms] SocketTube(10) got some demand for reading [2025-02-06T06:04:07.387Z] DEBUG: [pool-1-thread-1] [16s 831ms] SocketTube(10) resuming read event [2025-02-06T06:04:07.387Z] DEBUG: [pool-1-thread-5] [16s 828ms] SocketTube(14) leaving request(1): Reading: [ops=0, demand=1, stopped=true], Writing: [ops=0, demand=0] [2025-02-06T06:04:07.387Z] DEBUG: [pool-1-thread-4] [16s 829ms] Http2Connection(SSLTube(SocketTube(6))) Stopping scheduler java.net.SocketException: Connection reset [2025-02-06T06:04:07.387Z] java.net.SocketException: Connection reset [2025-02-06T06:04:07.387Z] at java.base/sun.nio.ch.SocketChannelImpl.throwConnectionReset(SocketChannelImpl.java:394) [2025-02-06T06:04:07.387Z] at java.base/sun.nio.ch.SocketChannelImpl.read(SocketChannelImpl.java:426) [2025-02-06T06:04:07.387Z] at java.net.http/jdk.internal.net.http.SocketTube.readAvailable(SocketTube.java:1170) [2025-02-06T06:04:07.387Z] at java.net.http/jdk.internal.net.http.SocketTube$InternalReadPublisher$InternalReadSubscription.read(SocketTube.java:833) [2025-02-06T06:04:07.387Z] at java.net.http/jdk.internal.net.http.SocketTube$SocketFlowTask.run(SocketTube.java:181) [2025-02-06T06:04:07.387Z] at java.net.http/jdk.internal.net.http.common.SequentialScheduler$SchedulableTask.run(SequentialScheduler.java:230) [2025-02-06T06:04:07.387Z] at java.net.http/jdk.internal.net.http.common.SequentialScheduler.runOrSchedule(SequentialScheduler.java:303) [2025-02-06T06:04:07.387Z] at java.net.http/jdk.internal.net.http.common.SequentialScheduler.runOrSchedule(SequentialScheduler.java:256) [2025-02-06T06:04:07.387Z] at java.net.http/jdk.internal.net.http.SocketTube$InternalReadPublisher$InternalReadSubscription.signalReadable(SocketTube.java:774) [2025-02-06T06:04:07.387Z] at java.net.http/jdk.internal.net.http.SocketTube$InternalReadPublisher$ReadEvent.signalEvent(SocketTube.java:957) [2025-02-06T06:04:07.387Z] at java.net.http/jdk.internal.net.http.SocketTube$SocketFlowEvent.handle(SocketTube.java:253) [2025-02-06T06:04:07.387Z] at java.net.http/jdk.internal.net.http.HttpClientImpl$SelectorManager.handleEvent(HttpClientImpl.java:984) [2025-02-06T06:04:07.387Z] at java.net.http/jdk.internal.net.http.HttpClientImpl$SelectorManager.lambda$run$3(HttpClientImpl.java:939) [2025-02-06T06:04:07.387Z] at java.base/java.util.ArrayList.forEach(ArrayList.java:1511) [2025-02-06T06:04:07.387Z] at java.net.http/jdk.internal.net.http.HttpClientImpl$SelectorManager.run(HttpClientImpl.java:939) [2025-02-06T06:04:07.387Z] DEBUG: [pool-1-thread-4] [16s 831ms] Http2Connection(SSLTube(SocketTube(6))) Shutting down h2c (closed=false): java.net.SocketException: Connection reset [2025-02-06T06:04:07.387Z] DEBUG: [pool-1-thread-4] [16s 831ms] Http2ClientImpl removing from the connection pool: Http2Connection(SSLTube(SocketTube(6))) [2025-02-06T06:04:07.387Z] DEBUG: [pool-1-thread-4] [16s 831ms] Http2ClientImpl removed from the connection pool: Http2Connection(SSLTube(SocketTube(6))) [2025-02-06T06:04:07.387Z] DEBUG: [pool-1-thread-4] [16s 831ms] PlainHttpConnection(SocketTube(6)) Closing channel: channel registered with selector, key.interestOps=1, sa.interestOps=1 [2025-02-06T06:04:07.387Z] DEBUG: [pool-1-thread-4] [16s 831ms] SocketTube(6) signal read error: java.io.IOException: connection closed locally [2025-02-06T06:04:07.387Z] DEBUG: [HttpClient-8-SelectorManager] [16s 829ms] SocketTube(9) pausing read event [2025-02-06T06:04:07.387Z] DEBUG: [HttpClient-8-SelectorManager] [16s 832ms] SocketTube(9) Sending error java.io.IOException: connection closed locally to subscriber READER: SubscriberWrapper: upstreamCompleted: false upstreamWindow: 0 downstreamCompleted: false completionAcknowledged: false outputQ size: 0 cf: jdk.internal.net.http.common.MinimalFuture@3672c195[Completed normally] (id=1042) downstreamSubscription: SubscriptionBase: window = 9223372036854775789 cancelled = true downstreamSubscriber: SSLSubscriberWrapper[SSLTube(SocketTube(9)), delegate: DelegateWrapper[subscribedCalled: true, subscribedDone: true, completed: false, error: null]: jdk.internal.net.http.Http2Connection$Http2TubeSubscriber@21130fb7, getALPN: jdk.internal.net.http.common.MinimalFuture@42c9ad19[Completed normally] (id=1048), onCompleteReceived: false, onError: null], readBuf: java.nio.HeapByteBuffer[pos=80 lim=80 cap=2048], count: 550, scheduler: running, status: CLOSED, handshakeState: 0, engine: NOT_HANDSHAKING [2025-02-06T06:04:07.387Z] DEBUG: [HttpClient-8-SelectorManager] [16s 832ms] SocketTube(9) Stopping read scheduler [2025-02-06T06:04:07.387Z] DEBUG: [HttpClient-8-SelectorManager] [16s 832ms] SocketTube(9) leaving read() loop with error: Reading: [ops=0, demand=0, stopped=true], Writing: [ops=0, demand=1] [2025-02-06T06:04:07.387Z] DEBUG: [HttpClient-8-SelectorManager] [16s 832ms] SocketTube(9) Read scheduler stopped [2025-02-06T06:04:07.387Z] DEBUG: [HttpClient-9-SelectorManager] [16s 829ms] Http2ClientImpl stopping [2025-02-06T06:04:07.387Z] DEBUG: [HttpClient-9-SelectorManager] [16s 832ms] AsyncSSLConnection(SSLTube(SocketTube(10))) added 34 bytes to the write queue [2025-02-06T06:04:07.387Z] DEBUG: [HttpClient-9-SelectorManager] [16s 832ms] AsyncSSLConnection(SSLTube(SocketTube(10))) signalling the publisher of the write queue [2025-02-06T06:04:07.387Z] DEBUG: [HttpClient-9-SelectorManager] [16s 832ms] AsyncSSLConnection(SSLTube(SocketTube(10))) HttpPublisher: sending 34 bytes (1 buffers) to SSLTube(SocketTube(10)) [2025-02-06T06:04:07.387Z] DEBUG: [HttpClient-9-SelectorManager] [16s 832ms] SSLTube(SocketTube(10)) sending 1 buffers to SSL flow delegate [2025-02-06T06:04:07.387Z] DEBUG: [HttpClient-9-SelectorManager] [16s 832ms] SSL Writer(SocketTube(10)) onNext [2025-02-06T06:04:07.387Z] DEBUG: [HttpClient-9-SelectorManager] [16s 832ms] SSL Writer(SocketTube(10)) added 1 (34 bytes) to the writeList [2025-02-06T06:04:07.387Z] DEBUG: [HttpClient-9-SelectorManager] [16s 832ms] SSL Writer(SocketTube(10)) processData, writeList remaining:34, hsTriggered:false, needWrap:false [2025-02-06T06:04:07.387Z] DEBUG: [HttpClient-9-SelectorManager] [16s 832ms] SSL Writer(SocketTube(10)) wrapping 34 bytes [2025-02-06T06:04:07.387Z] DEBUG: [HttpClient-9-SelectorManager] [16s 832ms] SSL Writer(SocketTube(10)) SSLResult: Status = CLOSED HandshakeStatus = NOT_HANDSHAKING [2025-02-06T06:04:07.387Z] bytesConsumed = 0 bytesProduced = 0 [2025-02-06T06:04:07.387Z] DEBUG: [HttpClient-9-SelectorManager] [16s 832ms] SSL Writer(SocketTube(10)) CLOSED [2025-02-06T06:04:07.387Z] DEBUG: [HttpClient-9-SelectorManager] [16s 832ms] SSL Writer(SocketTube(10)) OK => produced: 0 bytes into 0, not wrapped: 34 [2025-02-06T06:04:07.387Z] DEBUG: [HttpClient-9-SelectorManager] [16s 832ms] SSL Writer(SocketTube(10)) wrapBuffer returned Status = CLOSED HandshakeStatus = NOT_HANDSHAKING [2025-02-06T06:04:07.387Z] bytesConsumed = 0 bytesProduced = 0 [2025-02-06T06:04:07.387Z] DEBUG: [HttpClient-9-SelectorManager] [16s 832ms] Http2Connection(SSLTube(SocketTube(10))) Shutting down h2c (closed=false): java.io.EOFException: HTTP/2 client stopped [2025-02-06T06:04:07.387Z] DEBUG: [HttpClient-9-SelectorManager] [16s 832ms] Http2ClientImpl removing from the connection pool: Http2Connection(SSLTube(SocketTube(10))) [2025-02-06T06:04:07.387Z] DEBUG: [HttpClient-9-SelectorManager] [16s 832ms] Http2ClientImpl removed from the connection pool: Http2Connection(SSLTube(SocketTube(10))) [2025-02-06T06:04:07.388Z] DEBUG: [HttpClient-9-SelectorManager] [16s 832ms] SSL Reader(SocketTube(10)) stop [2025-02-06T06:04:07.388Z] DEBUG: [HttpClient-9-SelectorManager] [16s 832ms] SSL Writer(SocketTube(10)) stop [2025-02-06T06:04:07.388Z] DEBUG: [HttpClient-9-SelectorManager] [16s 832ms] PlainHttpConnection(SocketTube(10)) Closing channel: channel not registered with selector [2025-02-06T06:04:07.388Z] DEBUG: [HttpClient-9-SelectorManager] [16s 832ms] SocketTube(10) signal read error: java.io.IOException: connection closed locally [2025-02-06T06:04:07.388Z] DEBUG: [HttpClient-9-SelectorManager] [16s 832ms] SocketTube(10) got read error: java.io.IOException: connection closed locally [2025-02-06T06:04:07.388Z] DEBUG: [HttpClient-9-SelectorManager] [16s 832ms] SocketTube(10) pausing read event [2025-02-06T06:04:07.388Z] DEBUG: [HttpClient-9-SelectorManager] [16s 832ms] SocketTube(10) Sending error java.io.IOException: connection closed locally to subscriber READER: SubscriberWrapper: upstreamCompleted: false upstreamWindow: 1 downstreamCompleted: false completionAcknowledged: false outputQ size: 0 cf: jdk.internal.net.http.common.MinimalFuture@5c1c74b7[Completed normally] (id=1146) downstreamSubscription: SubscriptionBase: window = 9223372036854775789 cancelled = true downstreamSubscriber: SSLSubscriberWrapper[SSLTube(SocketTube(10)), delegate: DelegateWrapper[subscribedCalled: true, subscribedDone: true, completed: false, error: null]: jdk.internal.net.http.Http2Connection$Http2TubeSubscriber@206537a3, getALPN: jdk.internal.net.http.common.MinimalFuture@28cd19a5[Completed normally] (id=1152), onCompleteReceived: false, onError: null], readBuf: java.nio.HeapByteBuffer[pos=80 lim=80 cap=2048], count: 530, scheduler: stopped, status: CLOSED, handshakeState: 0, engine: NOT_HANDSHAKING [2025-02-06T06:04:07.388Z] DEBUG: [HttpClient-9-SelectorManager] [16s 832ms] SocketTube(10) Stopping read scheduler [2025-02-06T06:04:07.388Z] DEBUG: [HttpClient-9-SelectorManager] [16s 832ms] SocketTube(10) leaving read() loop with error: Reading: [ops=0, demand=1, stopped=true], Writing: [ops=0, demand=1] [2025-02-06T06:04:07.388Z] DEBUG: [HttpClient-9-SelectorManager] [16s 832ms] SocketTube(10) Read scheduler stopped [2025-02-06T06:04:07.388Z] DEBUG: [pool-1-thread-3] [16s 829ms] SocketTube(3) leaving requestMore: Reading: [ops=0, demand=0, stopped=false], Writing: [ops=0, demand=1] [2025-02-06T06:04:07.388Z] DEBUG: [pool-1-thread-3] [16s 832ms] SocketTube(3) leaving w.onNext Reading: [ops=0, demand=0, stopped=false], Writing: [ops=0, demand=1] [2025-02-06T06:04:07.388Z] DEBUG: [pool-1-thread-3] [16s 832ms] SSL Writer(SocketTube(3)) upstreamWindowUpdate, downstreamQueueSize:0, upstreamWindow:1 [2025-02-06T06:04:07.388Z] DEBUG: [pool-1-thread-3] [16s 832ms] SSL Writer(SocketTube(3)) DownstreamPusher: queue empty, downstreamSubscription: SubscriptionBase: window = 1 cancelled = false [2025-02-06T06:04:07.388Z] DEBUG: [pool-1-thread-3] [16s 832ms] SSL Writer(SocketTube(3)) completionAcknowledged upstreamCompleted:true, downstreamCompleted:false, closing:true [2025-02-06T06:04:07.388Z] DEBUG: [pool-1-thread-3] [16s 832ms] SSL Writer(SocketTube(3)) pushScheduler is alive [2025-02-06T06:04:07.388Z] DEBUG: [pool-1-thread-3] [16s 832ms] SSL Writer(SocketTube(3)) DownstreamPusher: queue empty, downstreamSubscription: SubscriptionBase: window = 1 cancelled = false [2025-02-06T06:04:07.388Z] DEBUG: [pool-1-thread-3] [16s 832ms] SSL Writer(SocketTube(3)) calling downstreamSubscriber.onComplete() [2025-02-06T06:04:07.388Z] DEBUG: [pool-1-thread-3] [16s 832ms] SocketTube(3) write completed, 0 yet to send [2025-02-06T06:04:07.388Z] DEBUG: [pool-1-thread-3] [16s 832ms] SocketTube(3) InternalWriteSubscriber::onComplete Reading: [ops=0, demand=0, stopped=false], Writing: [ops=0, demand=1] [2025-02-06T06:04:07.388Z] DEBUG: [pool-1-thread-3] [16s 832ms] SSL Writer(SocketTube(3)) processData, writeList remaining:0, hsTriggered:false, needWrap:false [2025-02-06T06:04:07.388Z] DEBUG: [pool-1-thread-3] [16s 832ms] SSL Reader(SocketTube(3)) Unwrapped: result: Status = CLOSED HandshakeStatus = NEED_WRAP [2025-02-06T06:04:07.388Z] bytesConsumed = 40 bytesProduced = 0 [2025-02-06T06:04:07.388Z] DEBUG: [pool-1-thread-3] [16s 832ms] SSL Reader(SocketTube(3)) Unwrapped: consumed: 40 [2025-02-06T06:04:07.388Z] DEBUG: [pool-1-thread-3] [16s 832ms] SSL Reader(SocketTube(3)) requesting 1 [2025-02-06T06:04:07.388Z] DEBUG: [pool-1-thread-3] [16s 832ms] SocketTube(3) got some demand for reading [2025-02-06T06:04:07.388Z] DEBUG: [pool-1-thread-3] [16s 832ms] SocketTube(3) resuming read event [2025-02-06T06:04:07.388Z] DEBUG: [pool-1-thread-3] [16s 832ms] SocketTube(3) leaving request(1): Reading: [ops=1, demand=1, stopped=false], Writing: [ops=0, demand=1] [2025-02-06T06:04:07.388Z] DEBUG: [pool-1-thread-3] [16s 832ms] SSL Reader(SocketTube(3)) processData: readBuf remaining:0, state: NOT_HANDSHAKING , engine handshake status:NOT_HANDSHAKING [2025-02-06T06:04:07.388Z] DEBUG: [pool-1-thread-1] [16s 832ms] SocketTube(10) leaving request(1): Reading: [ops=0, demand=1, stopped=true], Writing: [ops=0, demand=1] [2025-02-06T06:04:07.388Z] DEBUG: [pool-1-thread-2] [16s 829ms] SSL Writer(SocketTube(9)) DownstreamPusher: Pushing 40 bytes downstream [2025-02-06T06:04:07.388Z] DEBUG: [pool-1-thread-2] [16s 832ms] SocketTube(9) trying to write: 40 [2025-02-06T06:04:07.388Z] DEBUG: [pool-1-thread-2] [16s 832ms] SocketTube(9) write error: java.nio.channels.ClosedChannelException [2025-02-06T06:04:07.388Z] DEBUG: [pool-1-thread-2] [16s 832ms] SocketTube(9) error signalled java.nio.channels.ClosedChannelException [2025-02-06T06:04:07.388Z] DEBUG: [pool-1-thread-2] [16s 832ms] SocketTube(9) write: cancel [2025-02-06T06:04:07.388Z] DEBUG: [pool-1-thread-2] [16s 832ms] SocketTube(9) write: resetting demand to 0 [2025-02-06T06:04:07.388Z] DEBUG: [pool-1-thread-2] [16s 832ms] AsyncSSLConnection(SSLTube(SocketTube(9))) HttpPublisher: cancelled by SSLTube(SocketTube(9)) [2025-02-06T06:04:07.388Z] DEBUG: [pool-1-thread-2] [16s 832ms] SSL Reader(SocketTube(9)) stop [2025-02-06T06:04:07.388Z] DEBUG: [pool-1-thread-2] [16s 832ms] SSL Writer(SocketTube(9)) stop [2025-02-06T06:04:07.388Z] DEBUG: [pool-1-thread-2] [16s 832ms] SocketTube(9) leaving w.onNext Reading: [ops=0, demand=0, stopped=true], Writing: [ops=0, demand=0] [2025-02-06T06:04:07.388Z] DEBUG: [pool-1-thread-2] [16s 832ms] SSL Writer(SocketTube(9)) upstreamWindowUpdate, downstreamQueueSize:0, upstreamWindow:0 [2025-02-06T06:04:07.388Z] DEBUG: [pool-1-thread-2] [16s 832ms] SSL Writer(SocketTube(9)) requesting 1 [2025-02-06T06:04:07.388Z] DEBUG: [pool-1-thread-2] [16s 833ms] SSLTube(SocketTube(9)) request: n=1 [2025-02-06T06:04:07.388Z] DEBUG: [pool-1-thread-2] [16s 833ms] AsyncSSLConnection(SSLTube(SocketTube(9))) HttpPublisher: got request of 1 from SSLTube(SocketTube(9)) [2025-02-06T06:04:07.388Z] DEBUG: [pool-1-thread-2] [16s 833ms] SSL Writer(SocketTube(9)) wrapping 34 bytes [2025-02-06T06:04:07.388Z] DEBUG: [pool-1-thread-2] [16s 833ms] SSL Writer(SocketTube(9)) SSLResult: Status = CLOSED HandshakeStatus = NOT_HANDSHAKING [2025-02-06T06:04:07.388Z] bytesConsumed = 0 bytesProduced = 0 [2025-02-06T06:04:07.388Z] DEBUG: [pool-1-thread-2] [16s 833ms] SSL Writer(SocketTube(9)) CLOSED [2025-02-06T06:04:07.388Z] DEBUG: [pool-1-thread-2] [16s 833ms] SSL Writer(SocketTube(9)) OK => produced: 0 bytes into 0, not wrapped: 34 [2025-02-06T06:04:07.388Z] DEBUG: [pool-1-thread-2] [16s 833ms] SSL Writer(SocketTube(9)) wrapBuffer returned Status = CLOSED HandshakeStatus = NOT_HANDSHAKING [2025-02-06T06:04:07.388Z] bytesConsumed = 0 bytesProduced = 0 [2025-02-06T06:04:07.388Z] DEBUG: [pool-1-thread-2] [16s 833ms] SSL Reader(SocketTube(9)) Unwrapped: result: Status = CLOSED HandshakeStatus = NEED_WRAP [2025-02-06T06:04:07.388Z] bytesConsumed = 40 bytesProduced = 0 [2025-02-06T06:04:07.388Z] DEBUG: [pool-1-thread-2] [16s 833ms] SSL Reader(SocketTube(9)) Unwrapped: consumed: 40 [2025-02-06T06:04:07.388Z] DEBUG: [pool-1-thread-2] [16s 833ms] SSL Reader(SocketTube(9)) requesting 1 [2025-02-06T06:04:07.388Z] DEBUG: [pool-1-thread-2] [16s 833ms] SocketTube(9) subscription cancelled, ignoring request 1 [2025-02-06T06:04:07.388Z] DEBUG: [HttpClient-3-SelectorManager] [16s 833ms] SelectorAttachment Registering jdk.internal.net.http.SocketTube$InternalReadPublisher$ReadEvent@7a482468 for 1 (true) [2025-02-06T06:04:07.388Z] DEBUG: [HttpClient-3-SelectorManager] [16s 833ms] SelectorAttachment Registering jdk.internal.net.http.SocketTube$InternalReadPublisher$ReadEvent@7a482468 for 0 (false) [2025-02-06T06:04:07.388Z] DEBUG: [HttpClient-3-SelectorManager] [16s 833ms] SocketTube(3) signal read error: java.net.SocketException: Connection reset [2025-02-06T06:04:07.388Z] DEBUG: [HttpClient-3-SelectorManager] [16s 833ms] SocketTube(3) got read error: java.net.SocketException: Connection reset [2025-02-06T06:04:07.388Z] DEBUG: [HttpClient-3-SelectorManager] [16s 833ms] SocketTube(3) pausing read event [2025-02-06T06:04:07.388Z] DEBUG: [HttpClient-3-SelectorManager] [16s 833ms] SelectorAttachment Registering jdk.internal.net.http.SocketTube$InternalReadPublisher$ReadEvent@7a482468 for 0 (false) [2025-02-06T06:04:07.388Z] DEBUG: [HttpClient-3-SelectorManager] [16s 833ms] SocketTube(3) Sending error java.net.SocketException: Connection reset to subscriber READER: SubscriberWrapper: upstreamCompleted: false upstreamWindow: 1 downstreamCompleted: false completionAcknowledged: false outputQ size: 0 cf: jdk.internal.net.http.common.MinimalFuture@7e4ca83c[Not completed, 4 dependents] (id=246) downstreamSubscription: SubscriptionBase: window = 9223372036854775789 cancelled = false downstreamSubscriber: SSLSubscriberWrapper[SSLTube(SocketTube(3)), delegate: DelegateWrapper[subscribedCalled: true, subscribedDone: true, completed: false, error: null]: jdk.internal.net.http.Http2Connection$Http2TubeSubscriber@177ee6b2, getALPN: jdk.internal.net.http.common.MinimalFuture@6e61a509[Completed normally] (id=252), onCompleteReceived: false, onError: null], readBuf: java.nio.HeapByteBuffer[pos=40 lim=40 cap=2048], count: 550, scheduler: running, status: CLOSED, handshakeState: 0, engine: NOT_HANDSHAKING [2025-02-06T06:04:07.388Z] DEBUG: [HttpClient-3-SelectorManager] [16s 833ms] SocketTube(3) forwarding error to subscriber: java.net.SocketException: Connection reset [2025-02-06T06:04:07.388Z] DEBUG: [HttpClient-3-SelectorManager] [16s 833ms] SSL Reader(SocketTube(3)) onError: java.net.SocketException: Connection reset [2025-02-06T06:04:07.388Z] DEBUG: [HttpClient-3-SelectorManager] [16s 833ms] SSL Reader(SocketTube(3)) error java.net.SocketException: Connection reset [2025-02-06T06:04:07.388Z] java.net.SocketException: Connection reset [2025-02-06T06:04:07.388Z] at java.base/sun.nio.ch.SocketChannelImpl.throwConnectionReset(SocketChannelImpl.java:394) [2025-02-06T06:04:07.388Z] at java.base/sun.nio.ch.SocketChannelImpl.read(SocketChannelImpl.java:426) [2025-02-06T06:04:07.388Z] at java.net.http/jdk.internal.net.http.SocketTube.readAvailable(SocketTube.java:1170) [2025-02-06T06:04:07.388Z] at java.net.http/jdk.internal.net.http.SocketTube$InternalReadPublisher$InternalReadSubscription.read(SocketTube.java:833) [2025-02-06T06:04:07.388Z] at java.net.http/jdk.internal.net.http.SocketTube$SocketFlowTask.run(SocketTube.java:181) [2025-02-06T06:04:07.388Z] at java.net.http/jdk.internal.net.http.common.SequentialScheduler$SchedulableTask.run(SequentialScheduler.java:230) [2025-02-06T06:04:07.388Z] at java.net.http/jdk.internal.net.http.common.SequentialScheduler.runOrSchedule(SequentialScheduler.java:303) [2025-02-06T06:04:07.388Z] at java.net.http/jdk.internal.net.http.common.SequentialScheduler.runOrSchedule(SequentialScheduler.java:256) [2025-02-06T06:04:07.388Z] at java.net.http/jdk.internal.net.http.SocketTube$InternalReadPublisher$InternalReadSubscription.signalReadable(SocketTube.java:774) [2025-02-06T06:04:07.388Z] at java.net.http/jdk.internal.net.http.SocketTube$InternalReadPublisher$ReadEvent.signalEvent(SocketTube.java:957) [2025-02-06T06:04:07.388Z] at java.net.http/jdk.internal.net.http.SocketTube$SocketFlowEvent.handle(SocketTube.java:253) [2025-02-06T06:04:07.388Z] at java.net.http/jdk.internal.net.http.HttpClientImpl$SelectorManager.handleEvent(HttpClientImpl.java:984) [2025-02-06T06:04:07.388Z] at java.net.http/jdk.internal.net.http.HttpClientImpl$SelectorManager.lambda$run$3(HttpClientImpl.java:939) [2025-02-06T06:04:07.388Z] at java.base/java.util.ArrayList.forEach(ArrayList.java:1511) [2025-02-06T06:04:07.388Z] at java.net.http/jdk.internal.net.http.HttpClientImpl$SelectorManager.run(HttpClientImpl.java:939) [2025-02-06T06:04:07.388Z] DEBUG: [HttpClient-3-SelectorManager] [16s 833ms] SSL Reader(SocketTube(3)) DownstreamPusher: forwarding error downstream: java.net.SocketException: Connection reset [2025-02-06T06:04:07.388Z] DEBUG: [HttpClient-3-SelectorManager] [16s 833ms] SSLTube(SocketTube(3)) SSLSubscriberWrapper[SSLTube(SocketTube(3)), delegate: DelegateWrapper[subscribedCalled: true, subscribedDone: true, completed: false, error: null]: jdk.internal.net.http.Http2Connection$Http2TubeSubscriber@177ee6b2, getALPN: jdk.internal.net.http.common.MinimalFuture@6e61a509[Completed normally] (id=252), onCompleteReceived: false, onError: java.net.SocketException: Connection reset]: onErrorImpl: java.net.SocketException: Connection reset [2025-02-06T06:04:07.388Z] DEBUG: [HttpClient-3-SelectorManager] [16s 833ms] Http2Connection(SSLTube(SocketTube(3))) onError: java.net.SocketException: Connection reset [2025-02-06T06:04:07.388Z] DEBUG: [HttpClient-3-SelectorManager] [16s 833ms] SSLTube(SocketTube(3)) subscriber completed with error: java.net.SocketException: Connection reset [2025-02-06T06:04:07.388Z] DEBUG: [HttpClient-3-SelectorManager] [16s 833ms] AsyncSSLConnection(SSLTube(SocketTube(3))) HttpPublisher: cancelled by SSLTube(SocketTube(3)) [2025-02-06T06:04:07.388Z] DEBUG: [HttpClient-3-SelectorManager] [16s 833ms] SSL Reader(SocketTube(3)) stop [2025-02-06T06:04:07.388Z] DEBUG: [HttpClient-3-SelectorManager] [16s 833ms] SSL Writer(SocketTube(3)) stop [2025-02-06T06:04:07.388Z] DEBUG: [HttpClient-3-SelectorManager] [16s 833ms] SocketTube(3) Stopping read scheduler [2025-02-06T06:04:07.388Z] DEBUG: [HttpClient-3-SelectorManager] [16s 833ms] SocketTube(3) leaving read() loop with error: Reading: [ops=0, demand=0, stopped=true], Writing: [ops=0, demand=1] [2025-02-06T06:04:07.388Z] DEBUG: [HttpClient-3-SelectorManager] [16s 833ms] SocketTube(3) Read scheduler stopped [2025-02-06T06:04:07.388Z] DEBUG: [pool-1-thread-2] [16s 833ms] Http2Connection(SSLTube(SocketTube(3))) Stopping scheduler java.net.SocketException: Connection reset [2025-02-06T06:04:07.388Z] java.net.SocketException: Connection reset [2025-02-06T06:04:07.388Z] at java.base/sun.nio.ch.SocketChannelImpl.throwConnectionReset(SocketChannelImpl.java:394) [2025-02-06T06:04:07.388Z] at java.base/sun.nio.ch.SocketChannelImpl.read(SocketChannelImpl.java:426) [2025-02-06T06:04:07.388Z] at java.net.http/jdk.internal.net.http.SocketTube.readAvailable(SocketTube.java:1170) [2025-02-06T06:04:07.388Z] at java.net.http/jdk.internal.net.http.SocketTube$InternalReadPublisher$InternalReadSubscription.read(SocketTube.java:833) [2025-02-06T06:04:07.388Z] at java.net.http/jdk.internal.net.http.SocketTube$SocketFlowTask.run(SocketTube.java:181) [2025-02-06T06:04:07.388Z] at java.net.http/jdk.internal.net.http.common.SequentialScheduler$SchedulableTask.run(SequentialScheduler.java:230) [2025-02-06T06:04:07.388Z] at java.net.http/jdk.internal.net.http.common.SequentialScheduler.runOrSchedule(SequentialScheduler.java:303) [2025-02-06T06:04:07.388Z] at java.net.http/jdk.internal.net.http.common.SequentialScheduler.runOrSchedule(SequentialScheduler.java:256) [2025-02-06T06:04:07.388Z] at java.net.http/jdk.internal.net.http.SocketTube$InternalReadPublisher$InternalReadSubscription.signalReadable(SocketTube.java:774) [2025-02-06T06:04:07.388Z] at java.net.http/jdk.internal.net.http.SocketTube$InternalReadPublisher$ReadEvent.signalEvent(SocketTube.java:957) [2025-02-06T06:04:07.388Z] at java.net.http/jdk.internal.net.http.SocketTube$SocketFlowEvent.handle(SocketTube.java:253) [2025-02-06T06:04:07.388Z] at java.net.http/jdk.internal.net.http.HttpClientImpl$SelectorManager.handleEvent(HttpClientImpl.java:984) [2025-02-06T06:04:07.388Z] at java.net.http/jdk.internal.net.http.HttpClientImpl$SelectorManager.lambda$run$3(HttpClientImpl.java:939) [2025-02-06T06:04:07.388Z] at java.base/java.util.ArrayList.forEach(ArrayList.java:1511) [2025-02-06T06:04:07.388Z] at java.net.http/jdk.internal.net.http.HttpClientImpl$SelectorManager.run(HttpClientImpl.java:939) [2025-02-06T06:04:07.388Z] DEBUG: [pool-1-thread-2] [16s 833ms] Http2Connection(SSLTube(SocketTube(3))) Shutting down h2c (closed=false): java.net.SocketException: Connection reset [2025-02-06T06:04:07.388Z] DEBUG: [pool-1-thread-2] [16s 834ms] Http2ClientImpl removing from the connection pool: Http2Connection(SSLTube(SocketTube(3))) [2025-02-06T06:04:07.388Z] DEBUG: [pool-1-thread-2] [16s 834ms] Http2ClientImpl removed from the connection pool: Http2Connection(SSLTube(SocketTube(3))) [2025-02-06T06:04:07.388Z] DEBUG: [pool-1-thread-2] [16s 834ms] PlainHttpConnection(SocketTube(3)) Closing channel: channel registered with selector, key.interestOps=0, sa.interestOps=0 [2025-02-06T06:04:07.388Z] DEBUG: [pool-1-thread-2] [16s 834ms] SocketTube(3) signal read error: java.io.IOException: connection closed locally [2025-02-06T06:04:07.388Z] DEBUG: [HttpClient-5-SelectorManager] [16s 834ms] AsyncSSLConnection(SSLTube(SocketTube(6))) HttpPublisher: cancelled by SSLTube(SocketTube(6)) [2025-02-06T06:04:07.388Z] DEBUG: [HttpClient-5-SelectorManager] [16s 834ms] SSL Reader(SocketTube(6)) stop [2025-02-06T06:04:07.388Z] DEBUG: [HttpClient-5-SelectorManager] [16s 834ms] SSL Writer(SocketTube(6)) stop [2025-02-06T06:04:07.388Z] DEBUG: [HttpClient-5-SelectorManager] [16s 834ms] SocketTube(6) Stopping read scheduler [2025-02-06T06:04:07.389Z] DEBUG: [HttpClient-5-SelectorManager] [16s 834ms] SocketTube(6) leaving read() loop with error: Reading: [ops=0, demand=0, stopped=true], Writing: [ops=0, demand=1] [2025-02-06T06:04:07.389Z] DEBUG: [HttpClient-5-SelectorManager] [16s 834ms] SocketTube(6) Read scheduler stopped [2025-02-06T06:04:07.389Z] DEBUG: [HttpClient-5-SelectorManager] [16s 834ms] SelectorAttachment key cancelled for java.nio.channels.SocketChannel[closed] [2025-02-06T06:04:07.389Z] DEBUG: [HttpClient-5-SelectorManager] [16s 834ms] SocketTube(6) ReadEvent abort: java.io.IOException: java.nio.channels.CancelledKeyException [2025-02-06T06:04:07.389Z] DEBUG: [HttpClient-5-SelectorManager] [16s 834ms] SocketTube(6) signalError to jdk.internal.net.http.SocketTube$InternalReadPublisher$InternalReadSubscription@5f4c84fc (java.io.IOException: java.nio.channels.CancelledKeyException) [2025-02-06T06:04:07.389Z] DEBUG: [HttpClient-5-SelectorManager] [16s 834ms] SocketTube(6) signal read error: java.io.IOException: java.nio.channels.CancelledKeyException [2025-02-06T06:04:07.389Z] java.lang.Exception: failures: 1 [2025-02-06T06:04:07.389Z] at com.sun.javatest.regtest.agent.TestNGRunner.main(TestNGRunner.java:104) [2025-02-06T06:04:07.389Z] at com.sun.javatest.regtest.agent.TestNGRunner.main(TestNGRunner.java:58) [2025-02-06T06:04:07.389Z] at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method) [2025-02-06T06:04:07.389Z] at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:77) [2025-02-06T06:04:07.389Z] at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) [2025-02-06T06:04:07.389Z] at java.base/java.lang.reflect.Method.invoke(Method.java:569) [2025-02-06T06:04:07.389Z] at com.sun.javatest.regtest.agent.MainWrapper$MainTask.run(MainWrapper.java:138) [2025-02-06T06:04:07.389Z] at java.base/java.lang.Thread.run(Thread.java:840) [2025-02-06T06:04:07.389Z] [2025-02-06T06:04:07.389Z] JavaTest Message: Test threw exception: java.lang.Exception: failures: 1 [2025-02-06T06:04:07.389Z] JavaTest Message: shutting down test [2025-02-06T06:04:07.389Z] [2025-02-06T06:04:07.389Z] STATUS:Failed.`main' threw exception: java.lang.Exception: failures: 1 [2025-02-06T06:04:07.389Z] rerun: [2025-02-06T06:04:07.389Z] cd /Users/admin/workspace/workspace/Test_openjdk17_hs_extended.openjdk_x86-64_mac_testList_1/aqa-tests/TKG/output_17388008003671/jdk_net_0/work/scratch/1 && \ [2025-02-06T06:04:07.389Z] HOME=/Users/admin \ [2025-02-06T06:04:07.389Z] PATH=/bin:/usr/bin:/usr/sbin \ [2025-02-06T06:04:07.389Z] CLASSPATH=/Users/admin/workspace/workspace/Test_openjdk17_hs_extended.openjdk_x86-64_mac_testList_1/aqa-tests/TKG/output_17388008003671/jdk_net_0/work/classes/0/java/net/httpclient/DependentPromiseActionsTest.d:/Users/admin/workspace/workspace/Test_openjdk17_hs_extended.openjdk_x86-64_mac_testList_1/aqa-tests/openjdk/openjdk-jdk/test/jdk/java/net/httpclient:/Users/admin/workspace/workspace/Test_openjdk17_hs_extended.openjdk_x86-64_mac_testList_1/aqa-tests/TKG/output_17388008003671/jdk_net_0/work/classes/0/test/lib:/Users/admin/workspace/workspace/Test_openjdk17_hs_extended.openjdk_x86-64_mac_testList_1/aqa-tests/openjdk/openjdk-jdk/test/lib:/Users/admin/workspace/workspace/Test_openjdk17_hs_extended.openjdk_x86-64_mac_testList_1/aqa-tests/TKG/output_17388008003671/jdk_net_0/work/classes/0/test/jdk/java/net/httpclient/lib:/Users/admin/workspace/workspace/Test_openjdk17_hs_extended.openjdk_x86-64_mac_testList_1/aqa-tests/openjdk/openjdk-jdk/test/jdk/java/net/httpclient/lib:/Users/admin/workspace/workspace/Test_openjdk17_hs_extended.openjdk_x86-64_mac_testList_1/jvmtest/openjdk/jtreg/lib/testng-7.3.0.jar:/Users/admin/workspace/workspace/Test_openjdk17_hs_extended.openjdk_x86-64_mac_testList_1/jvmtest/openjdk/jtreg/lib/guice-5.1.0.jar:/Users/admin/workspace/workspace/Test_openjdk17_hs_extended.openjdk_x86-64_mac_testList_1/jvmtest/openjdk/jtreg/lib/jcommander-1.82.jar:/Users/admin/workspace/workspace/Test_openjdk17_hs_extended.openjdk_x86-64_mac_testList_1/jvmtest/openjdk/jtreg/lib/javatest.jar:/Users/admin/workspace/workspace/Test_openjdk17_hs_extended.openjdk_x86-64_mac_testList_1/jvmtest/openjdk/jtreg/lib/jtreg.jar \ [2025-02-06T06:04:07.389Z] /Users/admin/workspace/workspace/Test_openjdk17_hs_extended.openjdk_x86-64_mac_testList_1/jdkbinary/j2sdk-image/Contents/Home/bin/../bin/java \ [2025-02-06T06:04:07.389Z] -Dtest.vm.opts='-ea -esa -Xmx512m -XX:+UseCompressedOops' \ [2025-02-06T06:04:07.389Z] -Dtest.tool.vm.opts='-J-ea -J-esa -J-Xmx512m -J-XX:+UseCompressedOops' \ [2025-02-06T06:04:07.389Z] -Dtest.compiler.opts= \ [2025-02-06T06:04:07.389Z] -Dtest.java.opts= \ [2025-02-06T06:04:07.389Z] -Dtest.jdk=/Users/admin/workspace/workspace/Test_openjdk17_hs_extended.openjdk_x86-64_mac_testList_1/jdkbinary/j2sdk-image/Contents/Home/bin/.. \ [2025-02-06T06:04:07.389Z] -Dcompile.jdk=/Users/admin/workspace/workspace/Test_openjdk17_hs_extended.openjdk_x86-64_mac_testList_1/jdkbinary/j2sdk-image/Contents/Home/bin/.. \ [2025-02-06T06:04:07.389Z] -Dtest.timeout.factor=8.0 \ [2025-02-06T06:04:07.389Z] -Dtest.nativepath=/Users/admin/workspace/workspace/Test_openjdk17_hs_extended.openjdk_x86-64_mac_testList_1/jdkbinary/openjdk-test-image/jdk/jtreg/native \ [2025-02-06T06:04:07.389Z] -Dtest.root=/Users/admin/workspace/workspace/Test_openjdk17_hs_extended.openjdk_x86-64_mac_testList_1/aqa-tests/openjdk/openjdk-jdk/test/jdk \ [2025-02-06T06:04:07.389Z] -Dtest.name=java/net/httpclient/DependentPromiseActionsTest.java \ [2025-02-06T06:04:07.389Z] -Dtest.file=/Users/admin/workspace/workspace/Test_openjdk17_hs_extended.openjdk_x86-64_mac_testList_1/aqa-tests/openjdk/openjdk-jdk/test/jdk/java/net/httpclient/DependentPromiseActionsTest.java \ [2025-02-06T06:04:07.389Z] -Dtest.src=/Users/admin/workspace/workspace/Test_openjdk17_hs_extended.openjdk_x86-64_mac_testList_1/aqa-tests/openjdk/openjdk-jdk/test/jdk/java/net/httpclient \ [2025-02-06T06:04:07.389Z] -Dtest.src.path=/Users/admin/workspace/workspace/Test_openjdk17_hs_extended.openjdk_x86-64_mac_testList_1/aqa-tests/openjdk/openjdk-jdk/test/jdk/java/net/httpclient:/Users/admin/workspace/workspace/Test_openjdk17_hs_extended.openjdk_x86-64_mac_testList_1/aqa-tests/openjdk/openjdk-jdk/test/lib:/Users/admin/workspace/workspace/Test_openjdk17_hs_extended.openjdk_x86-64_mac_testList_1/aqa-tests/openjdk/openjdk-jdk/test/jdk/java/net/httpclient/lib \ [2025-02-06T06:04:07.389Z] -Dtest.classes=/Users/admin/workspace/workspace/Test_openjdk17_hs_extended.openjdk_x86-64_mac_testList_1/aqa-tests/TKG/output_17388008003671/jdk_net_0/work/classes/0/java/net/httpclient/DependentPromiseActionsTest.d \ [2025-02-06T06:04:07.389Z] -Dtest.class.path=/Users/admin/workspace/workspace/Test_openjdk17_hs_extended.openjdk_x86-64_mac_testList_1/aqa-tests/TKG/output_17388008003671/jdk_net_0/work/classes/0/java/net/httpclient/DependentPromiseActionsTest.d:/Users/admin/workspace/workspace/Test_openjdk17_hs_extended.openjdk_x86-64_mac_testList_1/aqa-tests/TKG/output_17388008003671/jdk_net_0/work/classes/0/test/lib:/Users/admin/workspace/workspace/Test_openjdk17_hs_extended.openjdk_x86-64_mac_testList_1/aqa-tests/TKG/output_17388008003671/jdk_net_0/work/classes/0/test/jdk/java/net/httpclient/lib \ [2025-02-06T06:04:07.389Z] -Dtest.class.path.prefix=/Users/admin/workspace/workspace/Test_openjdk17_hs_extended.openjdk_x86-64_mac_testList_1/aqa-tests/TKG/output_17388008003671/jdk_net_0/work/classes/0/java/net/httpclient/DependentPromiseActionsTest.d:/Users/admin/workspace/workspace/Test_openjdk17_hs_extended.openjdk_x86-64_mac_testList_1/aqa-tests/openjdk/openjdk-jdk/test/jdk/java/net/httpclient:/Users/admin/workspace/workspace/Test_openjdk17_hs_extended.openjdk_x86-64_mac_testList_1/aqa-tests/TKG/output_17388008003671/jdk_net_0/work/classes/0/test/lib:/Users/admin/workspace/workspace/Test_openjdk17_hs_extended.openjdk_x86-64_mac_testList_1/aqa-tests/TKG/output_17388008003671/jdk_net_0/work/classes/0/test/jdk/java/net/httpclient/lib \ [2025-02-06T06:04:07.389Z] -Dtest.modules='java.base/sun.net.www.http java.base/sun.net.www java.base/sun.net java.net.http/jdk.internal.net.http.common java.net.http/jdk.internal.net.http.frame java.net.http/jdk.internal.net.http.hpack java.logging jdk.httpserver' \ [2025-02-06T06:04:07.389Z] --add-modules java.base,java.net.http,java.logging,jdk.httpserver \ [2025-02-06T06:04:07.389Z] --add-exports java.base/sun.net.www.http=ALL-UNNAMED \ [2025-02-06T06:04:07.389Z] --add-exports java.base/sun.net.www=ALL-UNNAMED \ [2025-02-06T06:04:07.389Z] --add-exports java.base/sun.net=ALL-UNNAMED \ [2025-02-06T06:04:07.389Z] --add-exports java.net.http/jdk.internal.net.http.common=ALL-UNNAMED \ [2025-02-06T06:04:07.389Z] --add-exports java.net.http/jdk.internal.net.http.frame=ALL-UNNAMED \ [2025-02-06T06:04:07.389Z] --add-exports java.net.http/jdk.internal.net.http.hpack=ALL-UNNAMED \ [2025-02-06T06:04:07.389Z] -ea \ [2025-02-06T06:04:07.389Z] -esa \ [2025-02-06T06:04:07.389Z] -Xmx512m \ [2025-02-06T06:04:07.389Z] -XX:+UseCompressedOops \ [2025-02-06T06:04:07.389Z] -Djava.library.path=/Users/admin/workspace/workspace/Test_openjdk17_hs_extended.openjdk_x86-64_mac_testList_1/jdkbinary/openjdk-test-image/jdk/jtreg/native \ [2025-02-06T06:04:07.389Z] -Djdk.internal.httpclient.debug=true \ [2025-02-06T06:04:07.389Z] com.sun.javatest.regtest.agent.MainWrapper /Users/admin/workspace/workspace/Test_openjdk17_hs_extended.openjdk_x86-64_mac_testList_1/aqa-tests/TKG/output_17388008003671/jdk_net_0/work/java/net/httpclient/DependentPromiseActionsTest.d/testng.0.jta java/net/httpclient/DependentPromiseActionsTest.java false DependentPromiseActionsTest [2025-02-06T06:04:07.389Z] [2025-02-06T06:04:07.389Z] TEST RESULT: Failed. Execution failed: `main' threw exception: java.lang.Exception: failures: 1 [2025-02-06T06:04:07.389Z] -------------------------------------------------- [2025-02-06T06:42:57.410Z] Test results: passed: 816; failed: 1 [2025-02-06T06:43:18.244Z] Report written to /Users/admin/workspace/workspace/Test_openjdk17_hs_extended.openjdk_x86-64_mac_testList_1/aqa-tests/TKG/output_17388008003671/jdk_net_0/report/html/report.html [2025-02-06T06:43:18.244Z] Results written to /Users/admin/workspace/workspace/Test_openjdk17_hs_extended.openjdk_x86-64_mac_testList_1/aqa-tests/TKG/output_17388008003671/jdk_net_0/work [2025-02-06T06:43:18.244Z] Error: Some tests failed or other problems occurred. [2025-02-06T06:43:18.244Z] ----------------------------------- [2025-02-06T06:43:18.244Z] jdk_net_0_FAILED [2025-02-06T06:43:18.244Z] ----------------------------------- [2025-02-06T06:43:18.244Z] [2025-02-06T06:43:18.244Z] TEST TEARDOWN: [2025-02-06T06:43:18.244Z] Nothing to be done for teardown. [2025-02-06T06:43:18.244Z] jdk_net_0 Finish Time: Wed Feb 5 22:43:16 2025 Epoch Time (ms): 1738824196125