[upstream][jdk17][nightly]默认选项下java/net/httpclient/HttpsTunnelAuthTest.java随机失败 #229
Description
https://tone.aliyun-inc.com/ws/xesljfzh/test_result/302714?tab=1
【环境准备】
登录环境：
ssh -o ServerAliveInterval=60 [email protected]
cd /home/dongzhichun/tone/run/jtreg/TEST_AJDK17
BINARY_URL=oss://compiler-ci-bucket/ajdk17/20240322-104330-035-#18-linux.x86_64.release.master-be0ba70e063d21552de08d96610a492091b68923.jdk.tar.gz
TEST_IMAGE=oss://compiler-ci-bucket/ajdk17/20240322-104330-035-#18-linux.x86_64.release.master-be0ba70e063d21552de08d96610a492091b68923.test-image.tar.gz
JTREG_URL=oss://compiler-ci-bucket/jdk/tools/jtreg-7.3.1.1.zip
JDK_REPO=https://codeup.aliyun.com/5f4e0dfe6207a1a8b17fa7cf/compiler-test/jdk17u.git
JDK_BRANCH=master
cd ~/tone/tone-matrix-compiler/common; ./ossutil.bin_$(arch) -i;cd -
alias oss="~/tone/tone-matrix-compiler/common/ossutil.bin_$(arch) -e oss-cn-hangzhou.aliyuncs.com -u jvm_dev -b ~/tone/tone-matrix-compiler/common/ossutil_bin/ossutil -o download -f -r"
部署二进制：
oss $BINARY_URL -l ${BINARY_URL##*/}
mkdir bin-ajdk17;tar -xf ${BINARY_URL##*/} -C bin-ajdk17
oss $TEST_IMAGE -l ${TEST_IMAGE##*/}
mkdir iamges-ajdk17;tar -xf ${TEST_IMAGE##*/} -C images-ajdk17
cd bin-ajdk17/ && export JAVA_HOME=$PWD ; export PATH=$JAVA_HOME/bin:$PATH ; export TEST_JDK_HOME=$JAVA_HOME && cd -
部署jtreg工具：
oss $JTREG_URL -l ${JTREG_URL##*/};unzip ${JTREG_URL##*/}
cd jtreg ;export JT_HOME=$PWD ; export PATH=$PWD/bin:$PATH;cd -
部署用例repo
git clone -b $JDK_BRANCH $JDK_REPO jdk-repo-ajdk17
执行以下命令：
test="jdk-repo-ajdk17/test/jdk/java/net/httpclient/HttpsTunnelAuthTest.java"
args="-Xmixed"
native=-nativepath:images-ajdk17/test-image/hotspot/jtreg/native/
jtreg -nr -v:fail,error -w tmp $args $native $test
【复现命令】
5000次复现1次
1579.log
index-1579.rar
export test=jdk-repo-ajdk17/test/jdk/java/net/httpclient/HttpsTunnelAuthTest.java
export native="-nativepath:images-ajdk17/test-image/hotspot/jtreg/native/"
export args="-Djdk.lang.processReaperUseDefaultStackSize=true -Dtest.wisp.socketAddress=www.alibabacloud.com -Xmixed -ea -esa"
function runJtreg() { jtreg $args -timeoutFactor:4 -v:fail,error,time -nr -w $dir/index-$1 $native $test &> $dir/$1.log ; if [[ 0 -ne $? ]] ; then echo -n "$1 " ; else rm -rf $dir/index-$1 $dir/$1.log ; fi ; } ; export -f runJtreg ; export dir="tmp-jtreg-"basename ${test##* } .java | sed "s|#|_|" ; rm -rf $dir ; mkdir -p $dir ; time seq 5000 | xargs -i -n 1 -P nproc bash -c "runJtreg {}" ; echo total fail number: ls $dir/*.log 2> /dev/null | wc | awk '{print $1}'
1579
real 78m22.019s
user 2372m44.207s
sys 95m23.353s
total fail number: 1
【对比测试】
dragonwell17 同样问题 3/5w次失败
oss://dragonwell/17.0.10.0.11+7/Alibaba_Dragonwell_Standard_17.0.10.0.11.7_x64_linux.tar.gz
7819.log
19367.log
22183.log
index-7819.rar
index-19367.rar
index-22183.rar
[dongzhichun@CompilerTest-x64-4 TEST_AJDK17]$ java -version
openjdk version "17.0.10" 2024-01-16
OpenJDK Runtime Environment (Alibaba Dragonwell Standard Edition)-17.0.10.0.11+7-GA (build 17.0.10+7)
OpenJDK 64-Bit Server VM (Alibaba Dragonwell Standard Edition)-17.0.10.0.11+7-GA (build 17.0.10+7, mixed mode, sharing)
[dongzhichun@CompilerTest-x64-4 TEST_AJDK17]$ java -Xinternalversion
OpenJDK 64-Bit Server VM (17.0.10+7) for linux-amd64 JRE (17.0.10+7), built on Jan 16 2024 00:00:00 by "dragonwell" with gcc 7.5.0
Temurin17同样问题 1/1.5w次失败
12455.log
index-12455.rar
oss://compiler-ci-bucket/openjdk/jdk-17.0.10-ga/OpenJDK17U-jdk_x64_linux_hotspot_17.0.10_7.tar.gz
[dongzhichun@CompilerTest-x64-4 TEST_DRAGONWELL17]$ java -version;java -Xinternalversion
openjdk version "17.0.10" 2024-01-16
OpenJDK Runtime Environment Temurin-17.0.10+7 (build 17.0.10+7)
OpenJDK 64-Bit Server VM Temurin-17.0.10+7 (build 17.0.10+7, mixed mode, sharing)
OpenJDK 64-Bit Server VM (17.0.10+7) for linux-amd64 JRE (17.0.10+7), built on Jan 16 2024 00:00:00 by "admin" with gcc 10.3.0
【用例日志】
STDOUT:
Socket bound to: localhost:37827 after 1 attempt(s)
Http1TestServer[localhost/127.0.0.1:37827]::addHandler DigestEchoServer$HttpNoAuthHandler@1d2eacaa, /
Http1TestContext::addFilter Passthrough Filter
Http1TestContext::addFilter Passthrough Filter
Http1TestServer: start
Socket bound to: localhost:40509 after 1 attempt(s)
Http1TestServer[localhost/127.0.0.1:40509]::addHandler DigestEchoServer$HttpNoAuthHandler@60b83343, /
Http1TestContext::addFilter Passthrough Filter
Http1TestContext::addFilter Passthrough Filter
Http1TestServer: start
Socket bound to: localhost:40059 after 1 attempt(s)
Http2TestServerImpl[localhost/127.0.0.1:40059]::addHandler DigestEchoServer$HttpNoAuthHandler@680ef501, /
Http2TestContext::addFilter Filter for BASIC authentication: [Basic Server Filter]:DigestEchoServer[PID=3184923,PORT=40059]:HTTP_2:https:SERVER:BASICSERVER
Http2TestContext::addFilter Passthrough Filter
Http2TestServerImpl: start
Testing HTTP_1_1, http, /foo/http1
Proxy is: [HTTP @ /127.0.0.1:53809]
Posting to HTTP_1_1 server at: http://localhost:37827/foo/http1 POST
Proxy: accepted new connection: Proxy connection 1, client sock:java.nio.channels.SocketChannel[connected local=/127.0.0.1:53809 remote=/127.0.0.1:44730]
POST http://localhost:37827/foo/http1 HTTP/1.1
Content-Length: 316
Host: localhost:37827
User-Agent: Java-http-client/17.0.5.0.5-AJDK
Proxy: content-length: 316
Proxy: request body with 407, closing connection
Proxy: unauthorized; 407 sent (131/131), linger: 2, nodelay: true
Proxy: closing connection id=1, linger: 2, nodelay: true
Proxy: drained: 0
Proxy: closing connection {Proxy connection 1, client sock:java.nio.channels.SocketChannel[connected ishut oshut local=/127.0.0.1:53809 remote=/127.0.0.1:44730]}
Unexpected exception: exiting: java.io.IOException: HTTP/1.1 header parser received no bytes
java.io.IOException: HTTP/1.1 header parser received no bytes
at java.net.http/jdk.internal.net.http.HttpClientImpl.send(HttpClientImpl.java:586)
at java.net.http/jdk.internal.net.http.HttpClientFacade.send(HttpClientFacade.java:123)
at HttpsTunnelAuthTest.test(HttpsTunnelAuthTest.java:261)
at HttpsTunnelAuthTest.main(HttpsTunnelAuthTest.java:186)
at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:77)
at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.base/java.lang.reflect.Method.invoke(Method.java:568)
at com.sun.javatest.regtest.agent.MainWrapper$MainTask.run(MainWrapper.java:138)
at java.base/java.lang.Thread.run(Thread.java:840)
Caused by: java.io.IOException: HTTP/1.1 header parser received no bytes
at java.net.http/jdk.internal.net.http.common.Utils.wrapWithExtraDetail(Utils.java:348)
at java.net.http/jdk.internal.net.http.Http1Response$HeadersReader.onReadError(Http1Response.java:675)
at java.net.http/jdk.internal.net.http.Http1AsyncReceiver.checkForErrors(Http1AsyncReceiver.java:302)
at java.net.http/jdk.internal.net.http.Http1AsyncReceiver.flush(Http1AsyncReceiver.java:268)
at java.net.http/jdk.internal.net.http.common.SequentialScheduler$LockingRestartableTask.run(SequentialScheduler.java:205)
at java.net.http/jdk.internal.net.http.common.SequentialScheduler$CompleteRestartableTask.run(SequentialScheduler.java:149)
at java.net.http/jdk.internal.net.http.common.SequentialScheduler$SchedulableTask.run(SequentialScheduler.java:230)
at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1136)
at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:635)
... 1 more
Caused by: java.net.SocketException: Connection reset
at java.base/sun.nio.ch.SocketChannelImpl.throwConnectionReset(SocketChannelImpl.java:394)
at java.base/sun.nio.ch.SocketChannelImpl.read(SocketChannelImpl.java:426)
at java.net.http/jdk.internal.net.http.SocketTube.readAvailable(SocketTube.java:1170)
at java.net.http/jdk.internal.net.http.SocketTube$InternalReadPublisher$InternalReadSubscription.read(SocketTube.java:833)
at java.net.http/jdk.internal.net.http.SocketTube$SocketFlowTask.run(SocketTube.java:181)
at java.net.http/jdk.internal.net.http.common.SequentialScheduler$SchedulableTask.run(SequentialScheduler.java:230)
at java.net.http/jdk.internal.net.http.common.SequentialScheduler.runOrSchedule(SequentialScheduler.java:303)
at java.net.http/jdk.internal.net.http.common.SequentialScheduler.runOrSchedule(SequentialScheduler.java:256)
at java.net.http/jdk.internal.net.http.SocketTube$InternalReadPublisher$InternalReadSubscription.signalReadable(SocketTube.java:774)
at java.net.http/jdk.internal.net.http.SocketTube$InternalReadPublisher$ReadEvent.signalEvent(SocketTube.java:957)
at java.net.http/jdk.internal.net.http.SocketTube$SocketFlowEvent.handle(SocketTube.java:253)
at java.net.http/jdk.internal.net.http.HttpClientImpl$SelectorManager.handleEvent(HttpClientImpl.java:979)
at java.net.http/jdk.internal.net.http.HttpClientImpl$SelectorManager.lambda$run$3(HttpClientImpl.java:934)
at java.base/java.util.ArrayList.forEach(ArrayList.java:1511)
at java.net.http/jdk.internal.net.http.HttpClientImpl$SelectorManager.run(HttpClientImpl.java:934)
Http1TestServer: stop
Http1TestServer: stop
Http2TestServerImpl: stop
STDERR:
DEBUG: [MainThread] [4ms] HttpClientImpl(1) proxySelector is java.net.ProxySelector$StaticProxySelector@2a0208aa (user-supplied=true)
DEBUG: [MainThread] [11ms] HttpClientImpl(1) ClientImpl (async) send http://localhost:37827/foo/http1 POST
DEBUG: [MainThread] [17ms] Exchange establishing exchange for http://localhost:37827/foo/http1 POST,
proxy=/127.0.0.1:53809
DEBUG: [MainThread] [18ms] ExchangeImpl get: HTTP/1.1: new Http1Exchange
DEBUG: [MainThread] [23ms] PlainProxyConnection(?) Initial receive buffer size is: 65536
DEBUG: [MainThread] [23ms] PlainProxyConnection(?) Initial send buffer size is: 8192
DEBUG: [MainThread] [29ms] Exchange checkFor407: all clear
DEBUG: [MainThread] [29ms] Http1Exchange Sending headers only
DEBUG: [MainThread] [32ms] Http1AsyncReceiver(SocketTube(1)) Subscribed pending jdk.internal.net.http.Http1Response$HeadersReader@b704e07 queue.isEmpty: true
DEBUG: [MainThread] [39ms] Http1AsyncReceiver(SocketTube(1)) delegate is now jdk.internal.net.http.Http1Response$HeadersReader@b704e07, demand=1, canRequestMore=true, queue.isEmpty=true
DEBUG: [MainThread] [39ms] Http1AsyncReceiver(SocketTube(1)) downstream subscription demand is 1
DEBUG: [MainThread] [42ms] Http1AsyncReceiver(SocketTube(1)) checkRequestMore: canRequestMore=true, hasDemand=true
DEBUG: [MainThread] [42ms] Http1AsyncReceiver(SocketTube(1)) downstream subscription demand is 1
DEBUG: [MainThread] [42ms] Http1AsyncReceiver(SocketTube(1)) checkRequestMore: canRequestMore=true, hasDemand=true
DEBUG: [MainThread] [42ms] Http1Exchange response created in advance
DEBUG: [MainThread] [42ms] Http1Exchange initiating connect async
DEBUG: [MainThread] [43ms] PlainProxyConnection(SocketTube(1)) registering connect event
DEBUG: [HttpClient-1-SelectorManager] [44ms] SelectorAttachment Registering jdk.internal.net.http.PlainHttpConnection$ConnectEvent@32b11f22 for 8 (true)
DEBUG: [HttpClient-1-SelectorManager] [46ms] PlainProxyConnection(SocketTube(1)) ConnectEvent: finishing connect
DEBUG: [HttpClient-1-SelectorManager] [46ms] PlainProxyConnection(SocketTube(1)) ConnectEvent: connect finished: true, cancelled: false, Local addr: /127.0.0.1:44730
DEBUG: [HttpClient-1-Worker-0] [46ms] PlainProxyConnection(SocketTube(1)) finishConnect, setting connected=true
DEBUG: [HttpClient-1-Worker-0] [47ms] Http1Exchange SocketTube(1) connecting flows
DEBUG: [HttpClient-1-Worker-0] [47ms] SocketTube(1) connecting flows
DEBUG: [HttpClient-1-Worker-0] [47ms] SocketTube(1) read publisher got subscriber
DEBUG: [HttpClient-1-Worker-0] [47ms] SocketTube(1) registering subscribe event
DEBUG: [HttpClient-1-Worker-0] [47ms] SocketTube(1) leaving read.subscribe: Reading: [ops=0, demand=0, stopped=false], Writing: [ops=0, demand=0]
DEBUG: [HttpClient-1-SelectorManager] [47ms] SocketTube(1) subscribe event raised
DEBUG: [HttpClient-1-SelectorManager] [47ms] SocketTube(1) handling pending subscription for jdk.internal.net.http.Http1AsyncReceiver$Http1TubeSubscriber@5abd4367
DEBUG: [HttpClient-1-SelectorManager] [47ms] SocketTube(1) read demand reset to 0
DEBUG: [HttpClient-1-SelectorManager] [47ms] SocketTube(1) calling onSubscribe
DEBUG: [HttpClient-1-Worker-0] [47ms] Http1Publisher(SocketTube(1)) got subscriber: SocketTube(1)
DEBUG: [HttpClient-1-SelectorManager] [47ms] Http1AsyncReceiver(SocketTube(1)) Received onSubscribed from upstream
DEBUG: [HttpClient-1-Worker-0] [47ms] SocketTube(1) subscribed for writing
DEBUG: [HttpClient-1-SelectorManager] [48ms] SocketTube(1) onSubscribe called
DEBUG: [HttpClient-1-SelectorManager] [48ms] SocketTube(1) pending subscriber subscribed
DEBUG: [HttpClient-1-Worker-0] [48ms] SocketTube(1) write: registering startSubscription event
DEBUG: [HttpClient-1-Worker-1] [48ms] Http1AsyncReceiver(SocketTube(1)) downstream subscription demand is 1
DEBUG: [HttpClient-1-SelectorManager] [48ms] SocketTube(1) write: starting subscription
DEBUG: [HttpClient-1-Worker-1] [48ms] Http1AsyncReceiver(SocketTube(1)) checkRequestMore: canRequestMore=true, hasDemand=true
DEBUG: [HttpClient-1-SelectorManager] [48ms] SocketTube(1) write: offloading requestMore
DEBUG: [HttpClient-1-Worker-0] [48ms] Http1Exchange requestAction.headers
DEBUG: [HttpClient-1-Worker-1] [48ms] Http1AsyncReceiver(SocketTube(1)) Http1TubeSubscriber: requesting one more from upstream
DEBUG: [HttpClient-1-Worker-1] [48ms] SocketTube(1) got some demand for reading
DEBUG: [HttpClient-1-Worker-1] [48ms] SocketTube(1) resuming read event
DEBUG: [HttpClient-1-SelectorManager] [48ms] SelectorAttachment Registering jdk.internal.net.http.SocketTube$InternalReadPublisher$ReadEvent@273fc678 for 1 (true)
DEBUG: [HttpClient-1-Worker-1] [48ms] SocketTube(1) leaving request(1): Reading: [ops=1, demand=1, stopped=false], Writing: [ops=0, demand=1]
DEBUG: [HttpClient-1-Worker-2] [48ms] SocketTube(1) write: requesting more...
DEBUG: [HttpClient-1-Worker-2] [48ms] Http1Publisher(SocketTube(1)) subscription request(1), demand=1
DEBUG: [HttpClient-1-Worker-2] [48ms] Http1Publisher(SocketTube(1)) WriteTask
DEBUG: [HttpClient-1-Worker-2] [49ms] Http1Publisher(SocketTube(1)) hasOutgoing = false
DEBUG: [HttpClient-1-Worker-2] [49ms] SocketTube(1) leaving requestMore: Reading: [ops=1, demand=1, stopped=false], Writing: [ops=0, demand=1]
Apr 19, 2024 1:42:22 AM jdk.internal.net.http.Http1Request headers
INFO: REQUEST: http://localhost:37827/foo/http1 POST
Apr 19, 2024 1:42:22 AM jdk.internal.net.http.Http1Request logHeaders
INFO: HEADERS: REQUEST HEADERS:
POST http://localhost:37827/foo/http1 HTTP/1.1
Content-Length: 316
Host: localhost:37827
User-Agent: Java-http-client/17.0.5.0.5-AJDK
DEBUG: [HttpClient-1-Worker-0] [59ms] Http1Exchange setting outgoing with headers
DEBUG: [HttpClient-1-Worker-0] [60ms] Http1Exchange appending to outgoing DataPair [data=[java.nio.HeapByteBuffer[pos=0 lim=140 cap=140]], throwable=null]
DEBUG: [HttpClient-1-Worker-0] [60ms] Http1Publisher(SocketTube(1)) WriteTask
DEBUG: [HttpClient-1-Worker-0] [60ms] Http1Publisher(SocketTube(1)) hasOutgoing = true
DEBUG: [HttpClient-1-Worker-0] [60ms] Http1Exchange initiating completion of headersSentCF
DEBUG: [HttpClient-1-Worker-0] [61ms] Http1Publisher(SocketTube(1)) onNext with 140 bytes
DEBUG: [HttpClient-1-Worker-0] [61ms] SocketTube(1) trying to write: 140
DEBUG: [HttpClient-1-Worker-0] [61ms] SocketTube(1) wrote: 140
DEBUG: [HttpClient-1-Worker-0] [61ms] SocketTube(1) write: requesting more...
DEBUG: [HttpClient-1-Worker-0] [61ms] Http1Publisher(SocketTube(1)) subscription request(1), demand=1
DEBUG: [HttpClient-1-Worker-0] [61ms] SocketTube(1) leaving requestMore: Reading: [ops=1, demand=1, stopped=false], Writing: [ops=0, demand=1]
DEBUG: [HttpClient-1-Worker-0] [61ms] SocketTube(1) leaving w.onNext Reading: [ops=1, demand=1, stopped=false], Writing: [ops=0, demand=1]
DEBUG: [HttpClient-1-Worker-0] [62ms] Http1Publisher(SocketTube(1)) WriteTask
DEBUG: [HttpClient-1-Worker-0] [62ms] Http1Publisher(SocketTube(1)) hasOutgoing = false
DEBUG: [HttpClient-1-Worker-0] [62ms] Exchange checkFor407: all clear
DEBUG: [HttpClient-1-Worker-0] [62ms] Exchange sendRequestBody
DEBUG: [HttpClient-1-Worker-0] [62ms] Http1Exchange sendBodyAsync
DEBUG: [HttpClient-1-Worker-0] [62ms] Http1Exchange bodySubscriber is class jdk.internal.net.http.Http1Request$FixedContentSubscriber
DEBUG: [HttpClient-1-Worker-0] [63ms] Http1Exchange requesting more request body from the subscriber
DEBUG: [HttpClient-1-Worker-0] [63ms] jdk.internal.net.http.Http1Request@723261a0 Http1BodySubscriber requesting 1, from jdk.internal.net.http.PullPublisher$Subscription@10ad40ba
DEBUG: [HttpClient-1-Worker-0] [63ms] jdk.internal.net.http.Http1Request@723261a0 onNext
DEBUG: [HttpClient-1-Worker-0] [63ms] Http1Exchange appending to outgoing DataPair [data=[java.nio.HeapByteBuffer[pos=0 lim=316 cap=316]], throwable=null]
DEBUG: [HttpClient-1-Worker-0] [63ms] Http1Publisher(SocketTube(1)) WriteTask
DEBUG: [HttpClient-1-Worker-0] [63ms] Http1Publisher(SocketTube(1)) hasOutgoing = true
DEBUG: [HttpClient-1-Worker-0] [63ms] Http1Exchange requesting more request body from the subscriber
DEBUG: [HttpClient-1-Worker-0] [63ms] jdk.internal.net.http.Http1Request@723261a0 Http1BodySubscriber requesting 1, from jdk.internal.net.http.PullPublisher$Subscription@10ad40ba
DEBUG: [HttpClient-1-Worker-0] [63ms] Http1Publisher(SocketTube(1)) onNext with 316 bytes
DEBUG: [HttpClient-1-Worker-0] [63ms] SocketTube(1) trying to write: 316
DEBUG: [HttpClient-1-Worker-0] [63ms] SocketTube(1) wrote: 316
DEBUG: [HttpClient-1-Worker-0] [63ms] SocketTube(1) write: requesting more...
DEBUG: [HttpClient-1-Worker-0] [63ms] Http1Publisher(SocketTube(1)) subscription request(1), demand=1
DEBUG: [HttpClient-1-Worker-0] [64ms] SocketTube(1) leaving requestMore: Reading: [ops=0, demand=1, stopped=false], Writing: [ops=0, demand=1]
DEBUG: [HttpClient-1-SelectorManager] [64ms] SelectorAttachment Registering jdk.internal.net.http.SocketTube$InternalReadPublisher$ReadEvent@273fc678 for 0 (false)
DEBUG: [HttpClient-1-Worker-0] [64ms] SocketTube(1) leaving w.onNext Reading: [ops=0, demand=1, stopped=false], Writing: [ops=0, demand=1]
DEBUG: [HttpClient-1-Worker-0] [64ms] Http1Publisher(SocketTube(1)) WriteTask
DEBUG: [HttpClient-1-Worker-0] [64ms] Http1Publisher(SocketTube(1)) hasOutgoing = false
DEBUG: [HttpClient-1-Worker-0] [64ms] jdk.internal.net.http.Http1Request@723261a0 onComplete
DEBUG: [HttpClient-1-Worker-0] [64ms] Http1Exchange appending to outgoing DataPair [data=[java.nio.HeapByteBuffer[pos=0 lim=0 cap=0]], throwable=null]
DEBUG: [HttpClient-1-Worker-0] [64ms] Http1Publisher(SocketTube(1)) WriteTask
DEBUG: [HttpClient-1-Worker-0] [64ms] Http1Publisher(SocketTube(1)) hasOutgoing = true
DEBUG: [HttpClient-1-Worker-0] [64ms] Http1Exchange initiating completion of bodySentCF
DEBUG: [HttpClient-1-SelectorManager] [64ms] SocketTube(1) signal read error: java.net.SocketException: Connection reset
DEBUG: [HttpClient-1-SelectorManager] [64ms] SocketTube(1) got read error: java.net.SocketException: Connection reset
DEBUG: [HttpClient-1-SelectorManager] [64ms] SocketTube(1) pausing read event
DEBUG: [HttpClient-1-Worker-0] [64ms] Http1Publisher(SocketTube(1)) completed, stopping jdk.internal.net.http.common.SequentialScheduler@6ec3fe97
DEBUG: [HttpClient-1-SelectorManager] [64ms] SelectorAttachment Registering jdk.internal.net.http.SocketTube$InternalReadPublisher$ReadEvent@273fc678 for 0 (false)
DEBUG: [HttpClient-1-Worker-0] [64ms] Http1Exchange sendBodyAsync completed successfully
DEBUG: [HttpClient-1-SelectorManager] [64ms] SocketTube(1) Sending error java.net.SocketException: Connection reset to subscriber jdk.internal.net.http.Http1AsyncReceiver$Http1TubeSubscriber@5abd4367
DEBUG: [HttpClient-1-SelectorManager] [64ms] SocketTube(1) forwarding error to subscriber: java.net.SocketException: Connection reset
DEBUG: [HttpClient-1-SelectorManager] [64ms] Http1AsyncReceiver(SocketTube(1)) onError: java.net.SocketException: Connection reset
DEBUG: [HttpClient-1-Worker-0] [64ms] Http1Exchange reading headers
DEBUG: [HttpClient-1-Worker-0] [66ms] Http1Response(id=1, PlainProxyConnection(SocketTube(1))) Reading Headers: (remaining: 0) READING_HEADERS
DEBUG: [HttpClient-1-Worker-0] [66ms] Http1Response(id=1, PlainProxyConnection(SocketTube(1))) First time around
DEBUG: [HttpClient-1-Worker-0] [66ms] Http1Response(id=1, PlainProxyConnection(SocketTube(1))) headersReader is not yet completed
DEBUG: [HttpClient-1-SelectorManager] [68ms] Http1AsyncReceiver(SocketTube(1)) recorded jdk.internal.net.http.common.ConnectionExpiredException: subscription is finished
delegate: jdk.internal.net.http.Http1Response$HeadersReader@b704e07 queue.isEmpty: true jdk.internal.net.http.common.ConnectionExpiredException: subscription is finished
jdk.internal.net.http.common.ConnectionExpiredException: subscription is finished
at java.net.http/jdk.internal.net.http.Http1AsyncReceiver.onReadError(Http1AsyncReceiver.java:490)
at java.net.http/jdk.internal.net.http.Http1AsyncReceiver$Http1TubeSubscriber.onError(Http1AsyncReceiver.java:590)
at java.net.http/jdk.internal.net.http.SocketTube$InternalReadPublisher$ReadSubscription.signalCompletion(SocketTube.java:637)
at java.net.http/jdk.internal.net.http.SocketTube$InternalReadPublisher$InternalReadSubscription.read(SocketTube.java:821)
at java.net.http/jdk.internal.net.http.SocketTube$SocketFlowTask.run(SocketTube.java:181)
at java.net.http/jdk.internal.net.http.common.SequentialScheduler$SchedulableTask.run(SequentialScheduler.java:230)
at java.net.http/jdk.internal.net.http.common.SequentialScheduler.runOrSchedule(SequentialScheduler.java:303)
at java.net.http/jdk.internal.net.http.common.SequentialScheduler.runOrSchedule(SequentialScheduler.java:256)
at java.net.http/jdk.internal.net.http.SocketTube$InternalReadPublisher$InternalReadSubscription.signalReadable(SocketTube.java:774)
at java.net.http/jdk.internal.net.http.SocketTube$InternalReadPublisher$ReadEvent.signalEvent(SocketTube.java:957)
at java.net.http/jdk.internal.net.http.SocketTube$SocketFlowEvent.handle(SocketTube.java:253)
at java.net.http/jdk.internal.net.http.HttpClientImpl$SelectorManager.handleEvent(HttpClientImpl.java:979)
at java.net.http/jdk.internal.net.http.HttpClientImpl$SelectorManager.lambda$run$3(HttpClientImpl.java:934)
at java.base/java.util.ArrayList.forEach(ArrayList.java:1511)
at java.net.http/jdk.internal.net.http.HttpClientImpl$SelectorManager.run(HttpClientImpl.java:934)
Caused by: java.net.SocketException: Connection reset
at java.base/sun.nio.ch.SocketChannelImpl.throwConnectionReset(SocketChannelImpl.java:394)
at java.base/sun.nio.ch.SocketChannelImpl.read(SocketChannelImpl.java:426)
at java.net.http/jdk.internal.net.http.SocketTube.readAvailable(SocketTube.java:1170)
at java.net.http/jdk.internal.net.http.SocketTube$InternalReadPublisher$InternalReadSubscription.read(SocketTube.java:833)
... 11 more
Apr 19, 2024 1:42:22 AM jdk.internal.net.http.Http1AsyncReceiver onReadError
INFO: ERROR: HTTP/1 read subscriber recorded error: http://localhost:37827/foo/http1 POST - jdk.internal.net.http.common.ConnectionExpiredException: subscription is finished
Apr 19, 2024 1:42:22 AM jdk.internal.net.http.Http1AsyncReceiver onReadError
INFO: ERROR: HTTP/1 propagating recorded error: http://localhost:37827/foo/http1 POST - jdk.internal.net.http.common.ConnectionExpiredException: subscription is finished
DEBUG: [HttpClient-1-SelectorManager] [69ms] SocketTube(1) Stopping read scheduler
DEBUG: [HttpClient-1-SelectorManager] [69ms] SocketTube(1) leaving read() loop with error: Reading: [ops=0, demand=0, stopped=true], Writing: [ops=0, demand=1]
DEBUG: [HttpClient-1-SelectorManager] [69ms] SocketTube(1) Read scheduler stopped
DEBUG: [HttpClient-1-Worker-0] [69ms] Http1AsyncReceiver(SocketTube(1)) downstream subscription demand is 1
DEBUG: [HttpClient-1-Worker-0] [69ms] Http1AsyncReceiver(SocketTube(1)) checkRequestMore: canRequestMore=false, hasDemand=true
DEBUG: [HttpClient-1-Worker-0] [69ms] Http1AsyncReceiver(SocketTube(1)) Http1TubeSubscriber: no need to request more
DEBUG: [HttpClient-1-Worker-0] [69ms] Http1AsyncReceiver(SocketTube(1)) flushing jdk.internal.net.http.common.ConnectionExpiredException: subscription is finished
delegate: jdk.internal.net.http.Http1Response$HeadersReader@b704e07 queue.isEmpty: true
Apr 19, 2024 1:42:22 AM jdk.internal.net.http.Http1Response onReadError
INFO: ERROR: jdk.internal.net.http.common.ConnectionExpiredException: subscription is finished
at java.net.http/jdk.internal.net.http.common.Utils.wrapWithExtraDetail(Utils.java:349)
at java.net.http/jdk.internal.net.http.Http1Response$HeadersReader.onReadError(Http1Response.java:675)
at java.net.http/jdk.internal.net.http.Http1AsyncReceiver.checkForErrors(Http1AsyncReceiver.java:302)
at java.net.http/jdk.internal.net.http.Http1AsyncReceiver.flush(Http1AsyncReceiver.java:268)
at java.net.http/jdk.internal.net.http.common.SequentialScheduler$LockingRestartableTask.run(SequentialScheduler.java:205)
at java.net.http/jdk.internal.net.http.common.SequentialScheduler$CompleteRestartableTask.run(SequentialScheduler.java:149)
at java.net.http/jdk.internal.net.http.common.SequentialScheduler$SchedulableTask.run(SequentialScheduler.java:230)
at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1136)
at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:635)
at java.base/java.lang.Thread.run(Thread.java:840)
Caused by: java.io.IOException: HTTP/1.1 header parser received no bytes
at java.net.http/jdk.internal.net.http.common.Utils.wrapWithExtraDetail(Utils.java:348)
... 9 more
Caused by: java.net.SocketException: Connection reset
at java.base/sun.nio.ch.SocketChannelImpl.throwConnectionReset(SocketChannelImpl.java:394)
at java.base/sun.nio.ch.SocketChannelImpl.read(SocketChannelImpl.java:426)
at java.net.http/jdk.internal.net.http.SocketTube.readAvailable(SocketTube.java:1170)
at java.net.http/jdk.internal.net.http.SocketTube$InternalReadPublisher$InternalReadSubscription.read(SocketTube.java:833)
at java.net.http/jdk.internal.net.http.SocketTube$SocketFlowTask.run(SocketTube.java:181)
at java.net.http/jdk.internal.net.http.common.SequentialScheduler$SchedulableTask.run(SequentialScheduler.java:230)
at java.net.http/jdk.internal.net.http.common.SequentialScheduler.runOrSchedule(SequentialScheduler.java:303)
at java.net.http/jdk.internal.net.http.common.SequentialScheduler.runOrSchedule(SequentialScheduler.java:256)
at java.net.http/jdk.internal.net.http.SocketTube$InternalReadPublisher$InternalReadSubscription.signalReadable(SocketTube.java:774)
at java.net.http/jdk.internal.net.http.SocketTube$InternalReadPublisher$ReadEvent.signalEvent(SocketTube.java:957)
at java.net.http/jdk.internal.net.http.SocketTube$SocketFlowEvent.handle(SocketTube.java:253)
at java.net.http/jdk.internal.net.http.HttpClientImpl$SelectorManager.handleEvent(HttpClientImpl.java:979)
at java.net.http/jdk.internal.net.http.HttpClientImpl$SelectorManager.lambda$run$3(HttpClientImpl.java:934)
at java.base/java.util.ArrayList.forEach(ArrayList.java:1511)
at java.net.http/jdk.internal.net.http.HttpClientImpl$SelectorManager.run(HttpClientImpl.java:934)
DEBUG: [HttpClient-1-Worker-0] [71ms] Http1Response(id=1, PlainProxyConnection(SocketTube(1))) onReadError: cf is not yet completed
DEBUG: [HttpClient-1-Worker-0] [71ms] Http1Exchange getResponseAsync completed java.util.concurrent.CompletionException: jdk.internal.net.http.common.ConnectionExpiredException: subscription is finished
DEBUG: [HttpClient-1-Worker-0] [73ms] HttpClientImpl(1) ClientImpl (async) elapsed 60 millis for POST to http://localhost:37827/foo/http1
DEBUG: [HttpClient-1-Worker-0] [74ms] Http1Response(id=1, PlainProxyConnection(SocketTube(1))) closing connection: cause is jdk.internal.net.http.common.ConnectionExpiredException: subscription is finished
DEBUG: [HttpClient-1-Worker-0] [74ms] PlainProxyConnection(SocketTube(1)) Closing channel: channel registered with selector, key.interestOps=0, sa.interestOps=0
DEBUG: [HttpClient-1-Worker-0] [74ms] SocketTube(1) signal read error: java.io.IOException: connection closed locally
DEBUG: [HttpClient-1-Worker-0] [74ms] Http1Exchange asyncReceiver finished (failed=jdk.internal.net.http.common.ConnectionExpiredException: subscription is finished)
DEBUG: [HttpClient-1-Worker-0] [74ms] Http1Exchange asyncReceiver finished (failed=jdk.internal.net.http.common.ConnectionExpiredException: subscription is finished)
Server stopping 0 connections
java.io.IOException: HTTP/1.1 header parser received no bytes
at java.net.http/jdk.internal.net.http.HttpClientImpl.send(HttpClientImpl.java:586)
at java.net.http/jdk.internal.net.http.HttpClientFacade.send(HttpClientFacade.java:123)
at HttpsTunnelAuthTest.test(HttpsTunnelAuthTest.java:261)
at HttpsTunnelAuthTest.main(HttpsTunnelAuthTest.java:186)
at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:77)
at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.base/java.lang.reflect.Method.invoke(Method.java:568)
at com.sun.javatest.regtest.agent.MainWrapper$MainTask.run(MainWrapper.java:138)
at java.base/java.lang.Thread.run(Thread.java:840)
Caused by: java.io.IOException: HTTP/1.1 header parser received no bytes
at java.net.http/jdk.internal.net.http.common.Utils.wrapWithExtraDetail(Utils.java:348)
at java.net.http/jdk.internal.net.http.Http1Response$HeadersReader.onReadError(Http1Response.java:675)
at java.net.http/jdk.internal.net.http.Http1AsyncReceiver.checkForErrors(Http1AsyncReceiver.java:302)
at java.net.http/jdk.internal.net.http.Http1AsyncReceiver.flush(Http1AsyncReceiver.java:268)
at java.net.http/jdk.internal.net.http.common.SequentialScheduler$LockingRestartableTask.run(SequentialScheduler.java:205)
at java.net.http/jdk.internal.net.http.common.SequentialScheduler$CompleteRestartableTask.run(SequentialScheduler.java:149)
at java.net.http/jdk.internal.net.http.common.SequentialScheduler$SchedulableTask.run(SequentialScheduler.java:230)
at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1136)
at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:635)
... 1 more
Caused by: java.net.SocketException: Connection reset
at java.base/sun.nio.ch.SocketChannelImpl.throwConnectionReset(SocketChannelImpl.java:394)
at java.base/sun.nio.ch.SocketChannelImpl.read(SocketChannelImpl.java:426)
at java.net.http/jdk.internal.net.http.SocketTube.readAvailable(SocketTube.java:1170)
at java.net.http/jdk.internal.net.http.SocketTube$InternalReadPublisher$InternalReadSubscription.read(SocketTube.java:833)
at java.net.http/jdk.internal.net.http.SocketTube$SocketFlowTask.run(SocketTube.java:181)
at java.net.http/jdk.internal.net.http.common.SequentialScheduler$SchedulableTask.run(SequentialScheduler.java:230)
at java.net.http/jdk.internal.net.http.common.SequentialScheduler.runOrSchedule(SequentialScheduler.java:303)
at java.net.http/jdk.internal.net.http.common.SequentialScheduler.runOrSchedule(SequentialScheduler.java:256)
at java.net.http/jdk.internal.net.http.SocketTube$InternalReadPublisher$InternalReadSubscription.signalReadable(SocketTube.java:774)
at java.net.http/jdk.internal.net.http.SocketTube$InternalReadPublisher$ReadEvent.signalEvent(SocketTube.java:957)
at java.net.http/jdk.internal.net.http.SocketTube$SocketFlowEvent.handle(SocketTube.java:253)
at java.net.http/jdk.internal.net.http.HttpClientImpl$SelectorManager.handleEvent(HttpClientImpl.java:979)
at java.net.http/jdk.internal.net.http.HttpClientImpl$SelectorManager.lambda$run$3(HttpClientImpl.java:934)
at java.base/java.util.ArrayList.forEach(ArrayList.java:1511)
at java.net.http/jdk.internal.net.http.HttpClientImpl$SelectorManager.run(HttpClientImpl.java:934)
JavaTest Message: Test threw exception: java.io.IOException: HTTP/1.1 header parser received no bytes
JavaTest Message: shutting down test
STATUS:Failed.`main' threw exception: java.io.IOException: HTTP/1.1 header parser received no bytes
【版本信息】
[dongzhichun@CompilerTest-x64-4 TEST_AJDK17]$ uname -a ; cat /etc/os-release ; free -h ; lscpu | head -n 25 ; java -version ; java -Xinternalversion
Linux CompilerTest-x64-4 5.10.134-16.1.al8.x86_64 #1 SMP Thu Dec 7 14:11:24 UTC 2023 x86_64 x86_64 x86_64 GNU/Linux
NAME="Alibaba Cloud Linux"
VERSION="3 (Soaring Falcon)"
ID="alinux"
ID_LIKE="rhel fedora centos anolis"
VERSION_ID="3"
UPDATE_ID="9"
PLATFORM_ID="platform:al8"
PRETTY_NAME="Alibaba Cloud Linux 3 (Soaring Falcon)"
ANSI_COLOR="0;31"
HOME_URL="https://www.aliyun.com/"
total used free shared buff/cache available
Mem: 123Gi 883Mi 69Gi 38Mi 53Gi 121Gi
Swap: 0B 0B 0B
Architecture: x86_64
CPU op-mode(s): 32-bit, 64-bit
Byte Order: Little Endian
CPU(s): 32
On-line CPU(s) list: 0-31
Thread(s) per core: 2
Core(s) per socket: 16
Socket(s): 1
NUMA node(s): 1
Vendor ID: GenuineIntel
CPU family: 6
Model: 106
Model name: Intel(R) Xeon(R) Platinum 8369B CPU @ 2.70GHz
Stepping: 6
CPU MHz: 3506.659
BogoMIPS: 5399.99
Hypervisor vendor: KVM
Virtualization type: full
L1d cache: 48K
L1i cache: 32K
L2 cache: 1280K
L3 cache: 49152K
NUMA node0 CPU(s): 0-31
Flags: fpu vme de pse tsc msr pae mce cx8 apic sep mtrr pge mca cmov pat pse36 clflush mmx fxsr sse sse2 ss ht syscall nx pdpe1gb rdtscp lm constant_tsc rep_good nopl nonstop_tsc cpuid aperfmperf tsc_known_freq pni pclmulqdq monitor ssse3 fma cx16 pcid sse4_1 sse4_2 x2apic movbe popcnt aes xsave avx f16c rdrand hypervisor lahf_lm abm 3dnowprefetch cpuid_fault invpcid_single ibrs_enhanced fsgsbase tsc_adjust bmi1 avx2 smep bmi2 erms invpcid avx512f avx512dq rdseed adx smap avx512ifma clflushopt clwb avx512cd sha_ni avx512bw avx512vl xsaveopt xsavec xgetbv1 xsaves wbnoinvd arat avx512vbmi pku ospke avx512_vbmi2 gfni vaes vpclmulqdq avx512_vnni avx512_bitalg avx512_vpopcntdq rdpid fsrm arch_capabilities
openjdk version "17.0.5.0.5-AJDK" 2024-03-22
OpenJDK Runtime Environment (build 17.0.5.0.5-AJDK+0-Alibaba)
OpenJDK 64-Bit Server VM (build 17.0.5.0.5-AJDK+0-Alibaba, mixed mode, sharing)
OpenJDK 64-Bit Server VM (17.0.5.0.5-AJDK+0-Alibaba) for linux-amd64 JRE (17.0.5.0.5-AJDK+0-Alibaba), built on Mar 22 2024 02:49:21 by "" with gcc 7.3.1 20180303 (Red Hat 7.3.1-5)
Metadata
Metadata
Assignees
Labels
No labels