Bug #7092
SSL client accessing the remote url gets an exception
100%
Description
When I tested the Metacat replication between my local host and mn-demo-6, the task failed.
The tomcat log in mn-demo-6 is:
ERROR (edu.ucsb.nceas.metacat.replication.ReplicationService:getURLStream:2327) Unexpected Throwable encountered. Logging and moving on: org.apache.http.conn.ConnectionPoolTimeoutException: Timeout waiting for connection from pool
ERROR (edu.ucsb.nceas.metacat.replication.ReplicationService:getURLStream:2329) org.apache.http.conn.ConnectionPoolTimeoutException: Timeout waiting for connection from pool
at org.apache.http.impl.conn.PoolingHttpClientConnectionManager.leaseConnection(PoolingHttpClientConnectionManager.java:250)
at org.apache.http.impl.conn.PoolingHttpClientConnectionManager$1.get(PoolingHttpClientConnectionManager.java:227)
at org.apache.http.impl.execchain.MainClientExec.execute(MainClientExec.java:173)
at org.apache.http.impl.execchain.ProtocolExec.execute(ProtocolExec.java:195)
at org.apache.http.impl.execchain.RetryExec.execute(RetryExec.java:86)
at org.apache.http.impl.execchain.RedirectExec.execute(RedirectExec.java:108)
at org.apache.http.impl.client.InternalHttpClient.doExecute(InternalHttpClient.java:186)
at org.apache.http.impl.client.CloseableHttpClient.execute(CloseableHttpClient.java:82)
at org.apache.http.impl.client.CloseableHttpClient.execute(CloseableHttpClient.java:106)
at org.apache.http.impl.client.CloseableHttpClient.execute(CloseableHttpClient.java:57)
at org.dataone.client.rest.RestClient.doRequest(RestClient.java:294)
at org.dataone.client.rest.RestClient.doRequestNoBody(RestClient.java:230)
at org.dataone.client.rest.RestClient.doGetRequest(RestClient.java:148)
at edu.ucsb.nceas.metacat.replication.ReplicationService.getURLStream(ReplicationService.java:2311)
at edu.ucsb.nceas.metacat.replication.ReplicationService.getURLBytes(ReplicationService.java:2344)
at edu.ucsb.nceas.metacat.replication.ReplicationService.handleForceReplicateRequest(ReplicationService.java:662)
at edu.ucsb.nceas.metacat.replication.ReplicationServlet.handleGetOrPost(ReplicationServlet.java:156)
at edu.ucsb.nceas.metacat.replication.ReplicationServlet.doGet(ReplicationServlet.java:86)
at javax.servlet.http.HttpServlet.service(HttpServlet.java:620)
at javax.servlet.http.HttpServlet.service(HttpServlet.java:727)
at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:303)
at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:208)
at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:220)
at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:122)
at org.apache.catalina.authenticator.AuthenticatorBase.invoke(AuthenticatorBase.java:501)
at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:170)
at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:98)
at org.apache.catalina.valves.AccessLogValve.invoke(AccessLogValve.java:950)
at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:116)
at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:408)
at org.apache.coyote.ajp.AjpProcessor.process(AjpProcessor.java:193)
at org.apache.coyote.AbstractProtocol$AbstractConnectionHandler.process(AbstractProtocol.java:607)
at org.apache.tomcat.util.net.JIoEndpoint$SocketProcessor.run(JIoEndpoint.java:313)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
at java.lang.Thread.run(Thread.java:745)
ERROR (edu.ucsb.nceas.metacat.replication.ReplicationService:handleForceReplicateRequest:827) ReplicationService.handleForceReplicateRequest - An error occurred in replication. Please see the replication log at: /var/metacat/logs/metacatreplication.log
ERROR (edu.ucsb.nceas.metacat.replication.ReplicationService:handleForceReplicateRequest:828) ReplicationService.handleForceReplicateRequest - General error when adding doc tao.13302.1 to DB with action INSERT: org.apache.http.conn.ConnectionPoolTimeoutException: Timeout waiting for connection from pool
Here is the tomcat log from my local host:
688771 Thread-143 WARN ReplicationLogging - ForceReplicationHandler.run - sending message: https://mn-demo-6.test.dataone.org/knb/servlet/replication?action=forcereplicate&server=valley.duckdns.org/metacat/servlet/replication&docid=tao.13302.1&dbaction=INSERT
748990 Thread-143 ERROR ReplicationLogging - Unexpected Throwable encountered. Logging and moving on: java.net.SocketTimeoutException: Read timed out
748995 Thread-143 ERROR ReplicationLogging - java.net.SocketTimeoutException: Read timed out
at java.net.SocketInputStream.socketRead0(Native Method)
at java.net.SocketInputStream.read(SocketInputStream.java:152)
at java.net.SocketInputStream.read(SocketInputStream.java:122)
at sun.security.ssl.InputRecord.readFully(InputRecord.java:442)
at sun.security.ssl.InputRecord.read(InputRecord.java:480)
at sun.security.ssl.SSLSocketImpl.readRecord(SSLSocketImpl.java:934)
at sun.security.ssl.SSLSocketImpl.readDataRecord(SSLSocketImpl.java:891)
at sun.security.ssl.AppInputStream.read(AppInputStream.java:102)
at org.apache.http.impl.io.SessionInputBufferImpl.streamRead(SessionInputBufferImpl.java:136)
at org.apache.http.impl.io.SessionInputBufferImpl.fillBuffer(SessionInputBufferImpl.java:152)
at org.apache.http.impl.io.SessionInputBufferImpl.readLine(SessionInputBufferImpl.java:270)
at org.apache.http.impl.conn.DefaultHttpResponseParser.parseHead(DefaultHttpResponseParser.java:140)
at org.apache.http.impl.conn.DefaultHttpResponseParser.parseHead(DefaultHttpResponseParser.java:57)
at org.apache.http.impl.io.AbstractMessageParser.parse(AbstractMessageParser.java:260)
at org.apache.http.impl.DefaultBHttpClientConnection.receiveResponseHeader(DefaultBHttpClientConnection.java:161)
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:606)
at org.apache.http.impl.conn.CPoolProxy.invoke(CPoolProxy.java:138)
at com.sun.proxy.$Proxy30.receiveResponseHeader(Unknown Source)
at org.apache.http.protocol.HttpRequestExecutor.doReceiveResponse(HttpRequestExecutor.java:271)
at org.apache.http.protocol.HttpRequestExecutor.execute(HttpRequestExecutor.java:123)
at org.apache.http.impl.execchain.MainClientExec.execute(MainClientExec.java:254)
at org.apache.http.impl.execchain.ProtocolExec.execute(ProtocolExec.java:195)
at org.apache.http.impl.execchain.RetryExec.execute(RetryExec.java:86)
at org.apache.http.impl.execchain.RedirectExec.execute(RedirectExec.java:108)
at org.apache.http.impl.client.InternalHttpClient.doExecute(InternalHttpClient.java:186)
at org.apache.http.impl.client.CloseableHttpClient.execute(CloseableHttpClient.java:82)
at org.apache.http.impl.client.CloseableHttpClient.execute(CloseableHttpClient.java:106)
at org.apache.http.impl.client.CloseableHttpClient.execute(CloseableHttpClient.java:57)
at org.dataone.client.rest.RestClient.doRequest(RestClient.java:294)
at org.dataone.client.rest.RestClient.doRequestNoBody(RestClient.java:230)
at org.dataone.client.rest.RestClient.doGetRequest(RestClient.java:148)
at edu.ucsb.nceas.metacat.replication.ReplicationService.getURLStream(ReplicationService.java:2311)
at edu.ucsb.nceas.metacat.replication.ReplicationService.getURLContent(ReplicationService.java:2287)
at edu.ucsb.nceas.metacat.replication.ForceReplicationHandler.run(ForceReplicationHandler.java:328)
at java.lang.Thread.run(Thread.java:745)
748995 Thread-143 ERROR edu.ucsb.nceas.metacat.replication.ForceReplicationHandler - ForceReplicationHandler.run - An error occurred in replication. Please see the replication log at: /var/metacat/logs/metacatreplication.log
748995 Thread-143 ERROR ReplicationLogging - ForceReplicationHandler.run - Error in ForceReplicationHandler.run for server mn-demo-6.test.dataone.org/knb/servlet/replication : java.net.SocketTimeoutException: Read timed out
748995 Thread-143 WARN ReplicationLogging - ForceReplicationHandler.run - exiting ForceReplicationHandler Thread
History
#1 Updated by Rob Nahf almost 9 years ago
- % Done changed from 0 to 30
- Category set to Metacat
- Status changed from New to In Progress
- Assignee changed from Rob Nahf to Jing Tao
Reviewed Replication code and found a likely spot where problems were happening. ReplicationHandler.update() collects a list of open InputStreams from the other servers in its ring, and processes them. There was one spot in the method that returned from the method in the case of some sort of exception, but didn't manage the InputStream vector. I wrapped the whole method in a try / finally clause that ensures that all of the input streams in the vector are closed.
I did not do any testing on it. Jing maybe you can update your project and see how it works?
#2 Updated by Jing Tao almost 9 years ago
Hi Rob: it is getting better. The document can be replicated from my local host to mn-demo-6. There is no error on mn-demo-6. But in my local host (source) still has an error:
1036047 Thread-187 WARN ReplicationLogging - ForceReplicationHandler.run - sending message: https://mn-demo-6.test.dataone.org/knb/servlet/replication?action=forcereplicate&server=valley.duckdns.org/metacat/servlet/replication&docid=tao.13305.1&dbaction=INSERT
1096365 Thread-187 ERROR ReplicationLogging - Unexpected Throwable encountered. Logging and moving on: java.net.SocketTimeoutException: Read timed out
1096368 Thread-187 ERROR ReplicationLogging - java.net.SocketTimeoutException: Read timed out
at java.net.SocketInputStream.socketRead0(Native Method)
at java.net.SocketInputStream.read(SocketInputStream.java:152)
at java.net.SocketInputStream.read(SocketInputStream.java:122)
at sun.security.ssl.InputRecord.readFully(InputRecord.java:442)
at sun.security.ssl.InputRecord.read(InputRecord.java:480)
at sun.security.ssl.SSLSocketImpl.readRecord(SSLSocketImpl.java:934)
at sun.security.ssl.SSLSocketImpl.readDataRecord(SSLSocketImpl.java:891)
at sun.security.ssl.AppInputStream.read(AppInputStream.java:102)
at org.apache.http.impl.io.SessionInputBufferImpl.streamRead(SessionInputBufferImpl.java:136)
at org.apache.http.impl.io.SessionInputBufferImpl.fillBuffer(SessionInputBufferImpl.java:152)
at org.apache.http.impl.io.SessionInputBufferImpl.readLine(SessionInputBufferImpl.java:270)
at org.apache.http.impl.conn.DefaultHttpResponseParser.parseHead(DefaultHttpResponseParser.java:140)
at org.apache.http.impl.conn.DefaultHttpResponseParser.parseHead(DefaultHttpResponseParser.java:57)
at org.apache.http.impl.io.AbstractMessageParser.parse(AbstractMessageParser.java:260)
at org.apache.http.impl.DefaultBHttpClientConnection.receiveResponseHeader(DefaultBHttpClientConnection.java:161)
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:606)
at org.apache.http.impl.conn.CPoolProxy.invoke(CPoolProxy.java:138)
at com.sun.proxy.$Proxy30.receiveResponseHeader(Unknown Source)
at org.apache.http.protocol.HttpRequestExecutor.doReceiveResponse(HttpRequestExecutor.java:271)
at org.apache.http.protocol.HttpRequestExecutor.execute(HttpRequestExecutor.java:123)
at org.apache.http.impl.execchain.MainClientExec.execute(MainClientExec.java:254)
at org.apache.http.impl.execchain.ProtocolExec.execute(ProtocolExec.java:195)
at org.apache.http.impl.execchain.RetryExec.execute(RetryExec.java:86)
at org.apache.http.impl.execchain.RedirectExec.execute(RedirectExec.java:108)
at org.apache.http.impl.client.InternalHttpClient.doExecute(InternalHttpClient.java:186)
at org.apache.http.impl.client.CloseableHttpClient.execute(CloseableHttpClient.java:82)
at org.apache.http.impl.client.CloseableHttpClient.execute(CloseableHttpClient.java:106)
at org.apache.http.impl.client.CloseableHttpClient.execute(CloseableHttpClient.java:57)
at org.dataone.client.rest.RestClient.doRequest(RestClient.java:294)
at org.dataone.client.rest.RestClient.doRequestNoBody(RestClient.java:230)
at org.dataone.client.rest.RestClient.doGetRequest(RestClient.java:148)
at edu.ucsb.nceas.metacat.replication.ReplicationService.getURLStream(ReplicationService.java:2313)
at edu.ucsb.nceas.metacat.replication.ReplicationService.getURLContent(ReplicationService.java:2289)
at edu.ucsb.nceas.metacat.replication.ForceReplicationHandler.run(ForceReplicationHandler.java:328)
at java.lang.Thread.run(Thread.java:745)
1096368 Thread-187 ERROR edu.ucsb.nceas.metacat.replication.ForceReplicationHandler - ForceReplicationHandler.run - An error occurred in replication. Please see the replication log at: /var/metacat/logs/metacatreplication.log
1096368 Thread-187 ERROR ReplicationLogging - ForceReplicationHandler.run - Error in ForceReplicationHandler.run for server mn-demo-6.test.dataone.org/knb/servlet/replication : java.net.SocketTimeoutException: Read timed out
1096368 Thread-187 WARN ReplicationLogging - ForceReplicationHandler.run - exiting ForceReplicationHandler Thread
In D1URLFilter.
#3 Updated by Jing Tao almost 9 years ago
- Status changed from In Progress to Closed
- % Done changed from 30 to 100
In ReplicationServiceClass, the sslClient was a static class field. If two statement called it at different thread, it can cause the exception. When I change it to a local variable, the problem is fixed.
#4 Updated by Rob Nahf almost 9 years ago
HttpClient and this connection manager is built for multiple threads, but recommends setting a context for each thread. I don't think the Metacat replication code is set up well to accommodate this. If you plan to destroy the HttpClient every call, maybe you can reduce overhead by using the BasicClientConnectionManager. (https://hc.apache.org/httpcomponents-client-ga/httpclient/apidocs/org/apache/http/impl/conn/BasicClientConnectionManager.html)
#5 Updated by Jing Tao almost 9 years ago
But the BasicClientConnectionManager class is deprecated.
