search

googleads / googleads-java-lib

Google Ad Manager SOAP API Client Library for Java
Apache License 2.0
226 stars 360 forks source link

SSLHandshakeException: Remote host closed connection during handshake #155

Closed saidatta closed 6 years ago

saidatta commented 6 years ago

I asked this in the google-adwords-api forum and I was directed here.

......

javax.net.ssl.SSLHandshakeException: Remote host closed connection during handshake
        at sun.security.ssl.SSLSocketImpl.readRecord(SSLSocketImpl.java:1002)
        at sun.security.ssl.SSLSocketImpl.performInitialHandshake(SSLSocketImpl.java:1385)
        at sun.security.ssl.SSLSocketImpl.startHandshake(SSLSocketImpl.java:1413)
        at sun.security.ssl.SSLSocketImpl.startHandshake(SSLSocketImpl.java:1397)
.....
        at sun.reflect.GeneratedMethodAccessor107.invoke(Unknown Source)
        at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
        at java.lang.reflect.Method.invoke(Method.java:498)
        at com.google.api.ads.common.lib.soap.SoapClientHandler.invoke(SoapClientHandler.java:100)
        at com.google.api.ads.common.lib.soap.axis.AxisHandler.invokeSoapCall(AxisHandler.java:234)
        at com.google.api.ads.common.lib.soap.SoapServiceClient.callSoapClient(SoapServiceClient.java:63)
        at com.sun.proxy.$Proxy34.get(Unknown Source)
        at com.google.api.ads.adwords.extension.ratelimiter.ApiRateLimiter$1.call(ApiRateLimiter.java:51)
        at com.google.api.ads.adwords.extension.ratelimiter.ApiRateLimiter.run(ApiRateLimiter.java:59)
        at com.google.api.ads.adwords.extension.ratelimiter.ApiInvocationHandlerWithRateLimiter.handleInvocation(ApiInvocationHandlerWithRateLimiter.java:45)
        at com.google.common.reflect.AbstractInvocationHandler.invoke(AbstractInvocationHandler.java:84)
        at com.google.api.ads.adwords.axis.utils.v201806.shopping.ProductPartitionTreeImpl.createAdGroupTree(ProductPartitionTreeImpl.java:209)
        at com.google.api.ads.adwords.axis.utils.v201806.shopping.ProductPartitionTree.createAdGroupTree(ProductPartitionTree.java:83)
        at com.fanatics.marketing.pla_bid_down.handler.AdGroupHandler$1.run(AdGroupHandler.java:89)
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
        at java.lang.Thread.run(Thread.java:748)
Caused by: java.io.EOFException: SSL peer shut down incorrectly
        at sun.security.ssl.InputRecord.read(InputRecord.java:505)
.....

I have been getting the above stack trace for atleast couple of weeks. Any idea on what could have been the issue? I have tried placing

/bin/java -Dhttps.proxyHost=<host> -Dhttps.proxyPort=3128 -Dhttps.protocols=TLSv1.2... Java version - 8 and upgraded the adwords-api and adwords-extension-ratelimiter to the latest release, but it has been in vain. This happens whenever I try communicating with a Adwords API service. ( in the above example, it happens at com.google.api.ads.adwords.axis.utils.v201806.shopping.ProductPartitionTreeImpl.createAdGroupTree(ProductPartitionTreeImpl.java:209) )

Any hints or solutions would be highly helpful?

nwbirnie commented 6 years ago

Hey, Thanks for reporting this issue. It looks like there may be an issue connecting to your HTTPS proxy.

The stacktrace you provided looks incomplete though, is there a missing block between these two lines perhaps?

    at sun.security.ssl.SSLSocketImpl.startHandshake(SSLSocketImpl.java:1397)
    .....
    at sun.reflect.GeneratedMethodAccessor107.invoke(Unknown Source)

It would be great if you could attach that as well so that I can verify your proxy settings are being detected by the HTTPS client.

Best wishes, Nick

saidatta commented 6 years ago

Thanks for the reply.

The below is the request 

2018-10-15 17:35:40 INFO  soapXmlLogger:114 - SOAP request:
<?xml version="1.0" encoding="UTF-8" standalone="no"?>
<soapenv:Envelope xmlns:soapenv="http://schemas.xmlsoap.org/soap/envelope/" xmlns:xsd="http://www.w3.org/2001/XMLSchema" xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance">
    <soapenv:Header>
        <ns1:RequestHeader xmlns:ns1="https://adwords.google.com/api/adwords/cm/v201806" soapenv:mustUnderstand="0">
            <ns1:clientCustomerId>489-864-5465</ns1:clientCustomerId>
            <ns1:developerToken>REDACTED</ns1:developerToken>
            <ns1:userAgent>Raybeam (AwApi-Java, AdWords-Axis/4.1.0, Common-Java/4.1.0, Axis/1.4, Java/1.8.0_181, maven, SelectorBuilder, RateLimiterExtension)</ns1:userAgent>
            <ns1:validateOnly>false</ns1:validateOnly>
            <ns1:partialFailure>false</ns1:partialFailure>
        </ns1:RequestHeader>
    </soapenv:Header>
    <soapenv:Body>
        <get xmlns="https://adwords.google.com/api/adwords/cm/v201806">
            <serviceSelector>
                <fields>AdGroupId</fields>
                <fields>Id</fields>
                <fields>ParentCriterionId</fields>
                <fields>PartitionType</fields>
                <fields>CriteriaType</fields>
                <fields>CaseValue</fields>
                <fields>CpcBid</fields>
                <fields>CpcBidSource</fields>
                <fields>Status</fields>
                <fields>TrackingUrlTemplate</fields>
                <fields>UrlCustomParameters</fields>
                <predicates>
                    <field>AdGroupId</field>
                    <operator>EQUALS</operator>
                    <values>56678235006</values>
                </predicates>
                <predicates>
                    <field>CriteriaType</field>
                    <operator>EQUALS</operator>
                    <values>PRODUCT_PARTITION</values>
                </predicates>
                <predicates>
                    <field>Status</field>
                    <operator>IN</operator>
                    <values>ENABLED</values>
                    <values>PAUSED</values>
                </predicates>
                <paging>
                    <startIndex>4000</startIndex>
                    <numberResults>100</numberResults>
                </paging>
            </serviceSelector>
        </get>
    </soapenv:Body>
</soapenv:Envelope>

Here is the full stack trace response

2018-10-15 17:35:40 INFO  soapXmlLogger:115 - SOAP response:
<?xml version="1.0" encoding="UTF-8" standalone="no"?>
<soapenv:Envelope xmlns:soapenv="http://schemas.xmlsoap.org/soap/envelope/" xmlns:xsd="http://www.w3.org/2001/XMLSchema" xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance">
    <soapenv:Body>
        <soapenv:Fault>
            <faultcode>soapenv:Server.userException</faultcode>
            <faultstring>javax.net.ssl.SSLHandshakeException: Remote host closed connection during handshake</faultstring>
            <detail>
                <ns1:stackTrace xmlns:ns1="http://xml.apache.org/axis/">javax.net.ssl.SSLHandshakeException: Remote host closed connection during handshake
        at sun.security.ssl.SSLSocketImpl.readRecord(SSLSocketImpl.java:1002)
        at sun.security.ssl.SSLSocketImpl.performInitialHandshake(SSLSocketImpl.java:1385)
        at sun.security.ssl.SSLSocketImpl.startHandshake(SSLSocketImpl.java:1413)
        at sun.security.ssl.SSLSocketImpl.startHandshake(SSLSocketImpl.java:1397)
        at org.apache.axis.components.net.JSSESocketFactory.create(JSSESocketFactory.java:186)
        at org.apache.axis.transport.http.HTTPSender.getSocket(HTTPSender.java:191)
        at org.apache.axis.transport.http.HTTPSender.writeToSocket(HTTPSender.java:404)
        at org.apache.axis.transport.http.HTTPSender.invoke(HTTPSender.java:138)
        at org.apache.axis.strategies.InvocationStrategy.visit(InvocationStrategy.java:32)
        at org.apache.axis.SimpleChain.doVisiting(SimpleChain.java:118)
        at org.apache.axis.SimpleChain.invoke(SimpleChain.java:83)
        at org.apache.axis.client.AxisClient.invoke(AxisClient.java:165)
        at org.apache.axis.client.Call.invokeEngine(Call.java:2784)
        at org.apache.axis.client.Call.invoke(Call.java:2767)
        at org.apache.axis.client.Call.invoke(Call.java:2443)
        at org.apache.axis.client.Call.invoke(Call.java:2366)
        at org.apache.axis.client.Call.invoke(Call.java:1812)
        at com.google.api.ads.adwords.axis.v201806.cm.AdGroupCriterionServiceSoapBindingStub.get(AdGroupCriterionServiceSoapBindingStub.java:1688)
        at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
        at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
        at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
        at java.lang.reflect.Method.invoke(Method.java:498)
        at com.google.api.ads.common.lib.soap.SoapClientHandler.invoke(SoapClientHandler.java:100)
        at com.google.api.ads.common.lib.soap.axis.AxisHandler.invokeSoapCall(AxisHandler.java:234)
        at com.google.api.ads.common.lib.soap.SoapServiceClient.callSoapClient(SoapServiceClient.java:63)
        at com.google.api.ads.common.lib.soap.SoapServiceClient.invoke(SoapServiceClient.java:93)
        at com.sun.proxy.$Proxy34.get(Unknown Source)
        at sun.reflect.GeneratedMethodAccessor129.invoke(Unknown Source)
        at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
        at java.lang.reflect.Method.invoke(Method.java:498)
        at com.google.api.ads.adwords.extension.ratelimiter.ApiRateLimiter$1.call(ApiRateLimiter.java:51)
        at com.google.api.ads.adwords.extension.ratelimiter.ApiRetryHelper.callWithRetries(ApiRetryHelper.java:86)
        at com.google.api.ads.adwords.extension.ratelimiter.ApiRateLimiter.run(ApiRateLimiter.java:59)
        at com.google.api.ads.adwords.extension.ratelimiter.ApiInvocationHandlerWithRateLimiter.handleInvocation(ApiInvocationHandlerWithRateLimiter.java:45)
        at com.google.common.reflect.AbstractInvocationHandler.invoke(AbstractInvocationHandler.java:84)
        at com.sun.proxy.$Proxy34.get(Unknown Source)
        at com.google.api.ads.adwords.axis.utils.v201806.shopping.ProductPartitionTreeImpl.createAdGroupTree(ProductPartitionTreeImpl.java:209)
        at com.google.api.ads.adwords.axis.utils.v201806.shopping.ProductPartitionTree.createAdGroupTree(ProductPartitionTree.java:83)
        at com.fanatics.marketing.pla_bid_down.handler.AdGroupHandler$1.run(AdGroupHandler.java:89)
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
        at java.lang.Thread.run(Thread.java:748)
Caused by: java.io.EOFException: SSL peer shut down incorrectly
        at sun.security.ssl.InputRecord.read(InputRecord.java:505)
        at sun.security.ssl.SSLSocketImpl.readRecord(SSLSocketImpl.java:983)
        ... 41 more
</ns1:stackTrace>
                <ns2:hostname xmlns:ns2="http://xml.apache.org/axis/">ip-10-156-204-113</ns2:hostname>
            </detail>
        </soapenv:Fault>
    </soapenv:Body>
</soapenv:Envelope>
nwbirnie commented 6 years ago

So it could be that the proxy settings are being ignored by the socket factory. Could you add the following to your log4j.properties please and verify the output contains the proxy configuration?

log4j.logger.org.apache.axis.components.net=DEBUG

Additionally, you may have to configure the root logger if commons logging complains:

log4j.rootLogger=INFO, CONSOLE

You should see some lines like: 

DefaultSocketFactory: is tunnelInputStream null? false

The presence of that line shows that your connection is being routed via proxy.

saidatta commented 6 years ago

I didnt expect the proxy issue to happen because Weirdly, SSL handshake exception is kinda happening for accounts that have huge adGroups (with ~50) and the smaller adGroup accounts are succeeding.

nwbirnie commented 6 years ago

I noticed that we had a higher than expected latency a couple days before your initial report, so some valid requests may have failed. Could you retry some of these requests please and see if they complete as expected now?

However, I expect that this is not the root cause, since in your stack trace the exception occurs at SSLSocketImpl.performInitialHandshake(). This happens after the socket is connected, but before any account details are passed, so it's more likely to be a transport issue than account/backend related. That's why it looks suspiciously like the proxy is being ignored on some connect attempts. Could you please enable logging to check if this is the case? You should see the tunnelInputStream line mentioned above and Set up SSL tunnelling through <proxyhost>:<proxyport>.

saidatta commented 6 years ago

This problem has been there since July at that point I limited the usage of this API and was surprised it was still happening after I resumed it recently. I am seeing numerous Set up SSL tunnelling through <proxyhost>:<proxyport> and tunnelInputStream as specified after changing the logging level. So, handling with the proxy might not be the issue. Honestly, I tried everything setting the caCaerts truststore, protocols (TLS1,1.1,1.2), and proxies. I am kinda puzzled on whats happening.

The weird thing is I dont encounter the issue on other Adwords API interactions, and I use pretty much the same configurations.

I have a feeling it might be due to the amount of createAdGroupTree calls I am issuing, its causing something.

nwbirnie commented 6 years ago

It could simply be the case that you are issuing way too many concurrent calls and your requests are being dropped before they reach the API frontend. The general guidance is that you should have at most 15 concurrent threads accessing the AdWords API at a particular time. Could you try to reduce your overall request rate to the API, across all projects, and see if this improves the situation?

nwbirnie commented 6 years ago

Closing due to inactivity. Please feel free to reopen.

saidatta commented 6 years ago

To close the loop. it appears to have fixed. It was caused by too many requests, as the # of adgroups grew too big. Since, createAdGroup call creates numerous amounts of requests to get all the adgroups, it was eventually causing issues.

To fix it, for this problem, i was given the liberty to trim the adgroups.