Bug 62876

Summary: java.net.SocketException: Socket closed when using Proxy
Product: JMeter - Now in Github Reporter: michal.krajci
Component: HTTPAssignee: JMeter issues mailing list <issues>
Status: RESOLVED WORKSFORME    
Severity: normal CC: p.mouawad
Priority: P2 Keywords: FixedInTrunk
Version: 5.0   
Target Milestone: JMETER_5.1   
Hardware: All   
OS: All   

Description michal.krajci 2018-11-01 08:51:49 UTC 
I have test plan for testing complex functionality (45 requests). 
Thread Group is set as follow:
Number of Threads (users): 1
Ramp-Up Period (in seconds): 1
Loop Count: 1
When I ran this test plan it works nicely.
All requests are classic http requests (get or post) with json body data.
But when I add one SOAP request which go through proxy, then my requests start randomly (every run it is another different request) failed with this error.
java.net.SocketException: Socket closed
	at java.net.SocketInputStream.socketRead0(Native Method)
	at java.net.SocketInputStream.socketRead(SocketInputStream.java:116)
	at java.net.SocketInputStream.read(SocketInputStream.java:171)
	at java.net.SocketInputStream.read(SocketInputStream.java:141)
	at sun.security.ssl.InputRecord.readFully(InputRecord.java:465)
	at sun.security.ssl.InputRecord.read(InputRecord.java:503)
	at sun.security.ssl.SSLSocketImpl.readRecord(SSLSocketImpl.java:975)
	at sun.security.ssl.SSLSocketImpl.readDataRecord(SSLSocketImpl.java:933)
	at sun.security.ssl.AppInputStream.read(AppInputStream.java:105)
	at org.apache.http.impl.io.SessionInputBufferImpl.streamRead(SessionInputBufferImpl.java:137)
	at org.apache.http.impl.io.SessionInputBufferImpl.fillBuffer(SessionInputBufferImpl.java:153)
	at org.apache.http.impl.io.SessionInputBufferImpl.readLine(SessionInputBufferImpl.java:282)
	at org.apache.http.impl.conn.DefaultHttpResponseParser.parseHead(DefaultHttpResponseParser.java:138)
	at org.apache.http.impl.conn.DefaultHttpResponseParser.parseHead(DefaultHttpResponseParser.java:56)
	at org.apache.http.impl.io.AbstractMessageParser.parse(AbstractMessageParser.java:259)
	at org.apache.http.impl.DefaultBHttpClientConnection.receiveResponseHeader(DefaultBHttpClientConnection.java:163)
	at org.apache.http.impl.conn.CPoolProxy.receiveResponseHeader(CPoolProxy.java:165)
	at org.apache.http.protocol.HttpRequestExecutor.doReceiveResponse(HttpRequestExecutor.java:273)
	at org.apache.http.protocol.HttpRequestExecutor.execute(HttpRequestExecutor.java:125)
	at org.apache.http.impl.execchain.MainClientExec.execute(MainClientExec.java:272)
	at org.apache.http.impl.execchain.ProtocolExec.execute(ProtocolExec.java:185)
	at org.apache.http.impl.execchain.RetryExec.execute(RetryExec.java:89)
	at org.apache.http.impl.execchain.RedirectExec.execute(RedirectExec.java:110)
	at org.apache.http.impl.client.InternalHttpClient.doExecute(InternalHttpClient.java:185)
	at org.apache.http.impl.client.CloseableHttpClient.execute(CloseableHttpClient.java:83)
	at org.apache.jmeter.protocol.http.sampler.HTTPHC4Impl.executeRequest(HTTPHC4Impl.java:832)
	at org.apache.jmeter.protocol.http.sampler.HTTPHC4Impl.sample(HTTPHC4Impl.java:570)
	at org.apache.jmeter.protocol.http.sampler.HTTPSamplerProxy.sample(HTTPSamplerProxy.java:67)
	at org.apache.jmeter.protocol.http.sampler.HTTPSamplerBase.sample(HTTPSamplerBase.java:1231)
	at org.apache.jmeter.protocol.http.sampler.HTTPSamplerBase.sample(HTTPSamplerBase.java:1220)
	at org.apache.jmeter.threads.JMeterThread.doSampling(JMeterThread.java:622)
	at org.apache.jmeter.threads.JMeterThread.executeSamplePackage(JMeterThread.java:546)
	at org.apache.jmeter.threads.JMeterThread.processSampler(JMeterThread.java:486)
	at org.apache.jmeter.threads.JMeterThread.run(JMeterThread.java:253)
	at java.lang.Thread.run(Thread.java:748)

I try everything what I found for this error on google (change user.properties, system.properties, hc.parameters...), but nothing is working.
Comment 1 Philippe Mouawad 2018-11-01 14:41:50 UTC 
What makes you think it's a JMeter issue and not a proxy one ?

How did you configure Soap Request ?
Comment 2 michal.krajci 2018-11-05 05:42:28 UTC 
I think is jmeter issue because requests which failed, after I enable one soap request through proxy, normally working perfectrly. Request are failing after I enable this one request.
If I try it in soap-ui, request working fine.
My soap request is configured like normally post http request with https protocol, server IP and path end with .svc.
I have checked Follow Redirects and Use KeepAlive.
On the tab Advanced I have filled Server IP and Port number in section Proxy Server. Username and Password in this section are empty. Thats all how I configured soap request. Do I something wrong?
Comment 3 Philippe Mouawad 2018-12-21 21:09:48 UTC 
This bug is due to a bug in HTTPCLIENT.
See Bug 62852
Comment 4 Philippe Mouawad 2018-12-23 11:35:56 UTC 
Hello,
Could you test build:
https://builds.apache.org/job/JMeter-trunk/6993/artifact/trunk/dist/apache-jmeter-r1849600.zip

and confirm issue is fixed.

Thank you
Comment 5 Philippe Mouawad 2018-12-26 12:48:59 UTC 
Hello,
Any feedback? 

Thanks
Comment 6 michal.krajci 2019-01-07 05:24:37 UTC 
I'm sorry, that I write so late.
Can you please reupload zip file? I cant download it (404).
Comment 7 Philippe Mouawad 2019-01-07 06:08:39 UTC 
Hello,
You can download from here:

https://ci.apache.org/projects/jmeter/nightlies/

Thanks
Comment 8 michal.krajci 2019-01-07 07:18:23 UTC 
No, in this version I still have problems.
This is log output:
2019-01-07 08:07:07,120 INFO o.a.j.e.StandardJMeterEngine: Running the test!
2019-01-07 08:07:07,120 INFO o.a.j.s.SampleEvent: List of sample_variables: []
2019-01-07 08:07:07,124 INFO o.a.j.g.u.JMeterMenuBar: setRunning(true, *local*)
2019-01-07 08:07:07,126 INFO o.a.j.e.StandardJMeterEngine: Starting ThreadGroup: 1 : Thread Group
2019-01-07 08:07:07,126 INFO o.a.j.e.StandardJMeterEngine: Starting 1 threads for group Thread Group.
2019-01-07 08:07:07,126 INFO o.a.j.e.StandardJMeterEngine: Test will stop on error
2019-01-07 08:07:07,126 INFO o.a.j.t.ThreadGroup: Starting thread group... number=1 threads=1 ramp-up=1 perThread=1000.0 delayedStart=false
2019-01-07 08:07:07,132 INFO o.a.j.t.ThreadGroup: Started thread group number 1
2019-01-07 08:07:07,132 INFO o.a.j.e.StandardJMeterEngine: All thread groups have been started
2019-01-07 08:07:07,134 INFO o.a.j.t.JMeterThread: Thread started: Thread Group 1-1
2019-01-07 08:07:07,154 INFO o.a.j.m.JSR223PreProcessor: 2019-01-07T09:07:07.154
2019-01-07 08:07:07,155 DEBUG o.a.h.c.p.RequestAddCookies: CookieSpec selected: default
2019-01-07 08:07:07,155 DEBUG o.a.h.c.p.RequestAddCookies: Unsupported cookie policy: default
2019-01-07 08:07:07,155 DEBUG o.a.h.c.p.RequestAuthCache: Auth cache not set in the context
2019-01-07 08:07:07,156 DEBUG o.a.h.i.c.PoolingHttpClientConnectionManager: Connection request: [route: {s}->https://server.name:443][state: Thread Group 1-1][total kept alive: 0; route allocated: 0 of 2; total allocated: 0 of 20]
2019-01-07 08:07:07,156 DEBUG o.a.h.i.c.PoolingHttpClientConnectionManager: Connection leased: [id: 56][route: {s}->https://server.name:443][total kept alive: 0; route allocated: 1 of 2; total allocated: 1 of 20]
2019-01-07 08:07:07,156 DEBUG o.a.h.i.e.MainClientExec: Opening connection {s}->https://server.name:443
2019-01-07 08:07:07,156 DEBUG o.a.h.c.s.SSLConnectionSocketFactory: Connecting socket to server.name/172.27.185.170:443 with timeout 0
2019-01-07 08:07:07,188 DEBUG o.a.h.c.s.SSLConnectionSocketFactory: Enabled protocols: [TLSv1, TLSv1.1, TLSv1.2]
2019-01-07 08:07:07,188 DEBUG o.a.h.c.s.SSLConnectionSocketFactory: Enabled cipher suites:[TLS_ECDHE_ECDSA_WITH_AES_256_CBC_SHA384, TLS_ECDHE_RSA_WITH_AES_256_CBC_SHA384, TLS_RSA_WITH_AES_256_CBC_SHA256, TLS_ECDH_ECDSA_WITH_AES_256_CBC_SHA384, TLS_ECDH_RSA_WITH_AES_256_CBC_SHA384, TLS_DHE_RSA_WITH_AES_256_CBC_SHA256, TLS_DHE_DSS_WITH_AES_256_CBC_SHA256, TLS_ECDHE_ECDSA_WITH_AES_256_CBC_SHA, TLS_ECDHE_RSA_WITH_AES_256_CBC_SHA, TLS_RSA_WITH_AES_256_CBC_SHA, TLS_ECDH_ECDSA_WITH_AES_256_CBC_SHA, TLS_ECDH_RSA_WITH_AES_256_CBC_SHA, TLS_DHE_RSA_WITH_AES_256_CBC_SHA, TLS_DHE_DSS_WITH_AES_256_CBC_SHA, TLS_ECDHE_ECDSA_WITH_AES_128_CBC_SHA256, TLS_ECDHE_RSA_WITH_AES_128_CBC_SHA256, TLS_RSA_WITH_AES_128_CBC_SHA256, TLS_ECDH_ECDSA_WITH_AES_128_CBC_SHA256, TLS_ECDH_RSA_WITH_AES_128_CBC_SHA256, TLS_DHE_RSA_WITH_AES_128_CBC_SHA256, TLS_DHE_DSS_WITH_AES_128_CBC_SHA256, TLS_ECDHE_ECDSA_WITH_AES_128_CBC_SHA, TLS_ECDHE_RSA_WITH_AES_128_CBC_SHA, TLS_RSA_WITH_AES_128_CBC_SHA, TLS_ECDH_ECDSA_WITH_AES_128_CBC_SHA, TLS_ECDH_RSA_WITH_AES_128_CBC_SHA, TLS_DHE_RSA_WITH_AES_128_CBC_SHA, TLS_DHE_DSS_WITH_AES_128_CBC_SHA, TLS_ECDHE_ECDSA_WITH_AES_256_GCM_SHA384, TLS_ECDHE_ECDSA_WITH_AES_128_GCM_SHA256, TLS_ECDHE_RSA_WITH_AES_256_GCM_SHA384, TLS_RSA_WITH_AES_256_GCM_SHA384, TLS_ECDH_ECDSA_WITH_AES_256_GCM_SHA384, TLS_ECDH_RSA_WITH_AES_256_GCM_SHA384, TLS_DHE_RSA_WITH_AES_256_GCM_SHA384, TLS_DHE_DSS_WITH_AES_256_GCM_SHA384, TLS_ECDHE_RSA_WITH_AES_128_GCM_SHA256, TLS_RSA_WITH_AES_128_GCM_SHA256, TLS_ECDH_ECDSA_WITH_AES_128_GCM_SHA256, TLS_ECDH_RSA_WITH_AES_128_GCM_SHA256, TLS_DHE_RSA_WITH_AES_128_GCM_SHA256, TLS_DHE_DSS_WITH_AES_128_GCM_SHA256, TLS_EMPTY_RENEGOTIATION_INFO_SCSV]
2019-01-07 08:07:07,188 DEBUG o.a.h.c.s.SSLConnectionSocketFactory: Starting handshake
2019-01-07 08:07:07,250 DEBUG o.a.h.c.s.SSLConnectionSocketFactory: Secure session established
2019-01-07 08:07:07,250 DEBUG o.a.h.c.s.SSLConnectionSocketFactory:  negotiated protocol: TLSv1.2
2019-01-07 08:07:07,250 DEBUG o.a.h.c.s.SSLConnectionSocketFactory:  negotiated cipher suite: TLS_ECDHE_RSA_WITH_AES_256_GCM_SHA384
2019-01-07 08:07:07,250 DEBUG o.a.h.c.s.SSLConnectionSocketFactory:  peer principal: CN=*.monetplus.cz, C=CZ
2019-01-07 08:07:07,250 DEBUG o.a.h.c.s.SSLConnectionSocketFactory:  peer alternative names: [*.monetplus.cz, monetplus.cz]
2019-01-07 08:07:07,250 DEBUG o.a.h.c.s.SSLConnectionSocketFactory:  issuer principal: CN=SpaceSSL CA, OU=SpaceSSL Certification Authority, O=Unizeto Technologies S.A., C=PL
2019-01-07 08:07:07,250 DEBUG o.a.h.i.e.MainClientExec: Executing request POST /mep/fs/fta/transaction HTTP/1.1
2019-01-07 08:07:07,250 DEBUG o.a.h.i.e.MainClientExec: Target auth state: UNCHALLENGED
2019-01-07 08:07:07,250 DEBUG o.a.h.i.e.MainClientExec: Proxy auth state: UNCHALLENGED
2019-01-07 08:07:07,250 DEBUG o.a.h.headers: http-outgoing-56 >> POST /mep/fs/fta/transaction HTTP/1.1
2019-01-07 08:07:07,250 DEBUG o.a.h.headers: http-outgoing-56 >> Connection: keep-alive
2019-01-07 08:07:07,250 DEBUG o.a.h.headers: http-outgoing-56 >> Accept: application/json
2019-01-07 08:07:07,250 DEBUG o.a.h.headers: http-outgoing-56 >> Content-Type: application/json
2019-01-07 08:07:07,250 DEBUG o.a.h.headers: http-outgoing-56 >> Accept-Language: cs
2019-01-07 08:07:07,251 DEBUG o.a.h.headers: http-outgoing-56 >> X-TRN-ID: 68a336e6-0b94-43db-ab6d-535bfcf5b01a
2019-01-07 08:07:07,251 DEBUG o.a.h.headers: http-outgoing-56 >> Connection: keep-alive
2019-01-07 08:07:07,251 DEBUG o.a.h.headers: http-outgoing-56 >> Content-Length: 1452
2019-01-07 08:07:07,251 DEBUG o.a.h.headers: http-outgoing-56 >> Host: server.name
2019-01-07 08:07:07,251 DEBUG o.a.h.headers: http-outgoing-56 >> User-Agent: Apache-HttpClient/4.5.6 (Java/1.8.0_191)
2019-01-07 08:07:07,251 DEBUG o.a.h.wire: http-outgoing-56 >> "POST /mep/fs/fta/transaction HTTP/1.1[\r][\n]"
2019-01-07 08:07:07,251 DEBUG o.a.h.wire: http-outgoing-56 >> "Connection: keep-alive[\r][\n]"
2019-01-07 08:07:07,251 DEBUG o.a.h.wire: http-outgoing-56 >> "Accept: application/json[\r][\n]"
2019-01-07 08:07:07,251 DEBUG o.a.h.wire: http-outgoing-56 >> "Content-Type: application/json[\r][\n]"
2019-01-07 08:07:07,251 DEBUG o.a.h.wire: http-outgoing-56 >> "Accept-Language: cs[\r][\n]"
2019-01-07 08:07:07,251 DEBUG o.a.h.wire: http-outgoing-56 >> "X-TRN-ID: 68a336e6-0b94-43db-ab6d-535bfcf5b01a[\r][\n]"
2019-01-07 08:07:07,251 DEBUG o.a.h.wire: http-outgoing-56 >> "Connection: keep-alive[\r][\n]"
2019-01-07 08:07:07,251 DEBUG o.a.h.wire: http-outgoing-56 >> "Content-Length: 1452[\r][\n]"
2019-01-07 08:07:07,251 DEBUG o.a.h.wire: http-outgoing-56 >> "Host: server.name[\r][\n]"
2019-01-07 08:07:07,251 DEBUG o.a.h.wire: http-outgoing-56 >> "User-Agent: Apache-HttpClient/4.5.6 (Java/1.8.0_191)[\r][\n]"
2019-01-07 08:07:07,251 DEBUG o.a.h.wire: http-outgoing-56 >> "[\r][\n]"
2019-01-07 08:07:07,251 DEBUG o.a.h.wire: http-outgoing-56 >> "{ [\r][\n]"
2019-01-07 08:07:07,251 DEBUG o.a.h.wire: http-outgoing-56 >> "    "attribute1" : "name", [\r][\n]"
2019-01-07 08:07:07,251 DEBUG o.a.h.wire: http-outgoing-56 >> "    "attribute2" : "2018-08-02-42.07.77.123900",[\r][\n]"
2019-01-07 08:07:07,251 DEBUG o.a.h.wire: http-outgoing-56 >> "    "attribute3" : "web", [\r][\n]"
2019-01-07 08:07:07,251 DEBUG o.a.h.wire: http-outgoing-56 >> "}"
2019-01-07 08:07:08,155 DEBUG o.a.h.i.e.MainClientExec: Cancelling request execution
2019-01-07 08:07:08,155 DEBUG o.a.h.i.c.DefaultManagedHttpClientConnection: http-outgoing-56: Shutdown connection
2019-01-07 08:07:08,157 DEBUG o.a.h.wire: http-outgoing-56 << "[read] I/O error: Socket closed"
2019-01-07 08:07:08,157 DEBUG o.a.h.i.e.MainClientExec: Connection discarded
2019-01-07 08:07:08,157 DEBUG o.a.h.i.e.RetryExec: Request has been aborted
2019-01-07 08:07:08,157 DEBUG o.a.h.i.c.PoolingHttpClientConnectionManager: Connection released: [id: 56][route: {s}->https://server.name:443][total kept alive: 0; route allocated: 0 of 2; total allocated: 0 of 20]
2019-01-07 08:07:08,157 WARN o.a.j.m.SampleTimeout: Call Done interrupting HTTPSamplerProxy @1305861290 '1.1 - register transaction'  took 0.002133907 secs
2019-01-07 08:07:08,167 INFO o.a.j.t.JMeterThread: Shutdown Test detected by thread: Thread Group 1-1
2019-01-07 08:07:08,167 INFO o.a.j.t.JMeterThread: Thread finished: Thread Group 1-1
2019-01-07 08:07:08,167 DEBUG o.a.h.i.c.PoolingHttpClientConnectionManager: Connection manager is shutting down
2019-01-07 08:07:08,167 DEBUG o.a.h.i.c.PoolingHttpClientConnectionManager: Connection manager shut down
2019-01-07 08:07:08,168 INFO o.a.j.e.StandardJMeterEngine: Notifying test listeners of end of test
2019-01-07 08:07:08,167 INFO o.a.j.t.JMeterThread: Stopping: Thread Group 1-1
2019-01-07 08:07:08,168 INFO o.a.j.g.u.JMeterMenuBar: setRunning(false, *local*)



I dont know what is wrong.
Comment 9 Philippe Mouawad 2019-01-07 07:37:38 UTC 
Hello,
I see this log:
2019-01-07 08:07:08,157 WARN o.a.j.m.SampleTimeout: Call Done interrupting

So it seems you are using Sample Timeout element.
Can you remove it and try again ?

Thanks
Comment 10 michal.krajci 2019-01-07 08:08:04 UTC 
Yes, I have 1s timeouts in this test plan. But I need this timeouts. How can I handle this with timeouts?
Comment 11 Philippe Mouawad 2019-01-07 08:23:29 UTC 
(In reply to michal.krajci from comment #10)
> Yes, I have 1s timeouts in this test plan. But I need this timeouts. How can
> I handle this with timeouts?

Hello,
First, can you just remove it and see if it works ?

Then I'll answer.

Regards
Comment 12 michal.krajci 2019-01-07 08:25:50 UTC 
Sry, I forgot to write it. Yes it seems it works without timeouts.
Comment 13 Philippe Mouawad 2019-01-07 08:27:26 UTC 
Ok, so I'll close this one as WORKSFORME.

Regarding your question, why don't you use Advanced Tab either in HTTP REquest Defaults and HTTP Request to configure connect and read timeouts ?

This way you can customize it for longer queries .

Thanks
Comment 14 michal.krajci 2019-01-07 08:34:39 UTC 
In this test plan I have 5 requests and there must be a wait of at least 1s between each request (due to logic on the server).
Comment 15 Philippe Mouawad 2019-01-07 08:45:08 UTC 
Please use user mailing lists for such questions.

Why are you using SampleTimeout instead of Timers (you can also use Right click on parent node of Samplers and Add Think Time to Children) ?

SampleTimeout is for timeout not for adding delays between requests.
Comment 16 michal.krajci 2019-01-07 09:05:58 UTC 
Thanks it helps a lot.
Comment 17 Philippe Mouawad 2019-01-07 09:09:11 UTC 
(In reply to michal.krajci from comment #16)
> Thanks it helps a lot.

You're welcome , let people know that you're happy with Apache JMeter and team feedback :-)

And if you'd like to learn more about JMeter, this book might be helpful:

- https://leanpub.com/master-jmeter-from-load-test-to-devops


Regards
Comment 18 The ASF infrastructure team 2022-09-24 20:38:15 UTC 
This issue has been migrated to GitHub: https://github.com/apache/jmeter/issues/4908