Recently was working on an vRealize Automation environment 8.x version ( vCF based ) where an authenticated proxy was involved for external connectivity.
We were trying to add an VMware Cloud on AWS cloud account and it was failing with the below error
Looking into provisioning-service-app.log , we see the actual error
2021-10-05T04:06:51.975Z [priority='INFO' thread='reactor-http-epoll-13' user='' org='' context='' parent='' token=''] com.vmware.xenon.common.SpringHostUtils.responseEntityToOperation:901 - [POST https://console. cloud.vmware.com/csp/gateway/am/api/auth/api-tokens/authorize] Exception received with no ClientResponse: java.util.concurrent.CompletionException: javax.net.ssl.SSLException: failure when writing TLS control framesThe whole exceptions is as below
2021-10-05T04:06:51.726Z [priority='INFO' thread='reactor-http-epoll-15' user='arun' org='ce3fdd9b-f3f1-41f1-8622-7cb1e53fae71' context='f9899447-69e3-4843-bae0-303ace93b1e4' parent='' token='c2559493-fae 5-4faf-ba28-7f1fddcb58dc'] com.vmware.xenon.common.SpringHostUtils.sendRequest:233 - Sending POST http://10.244.10.110:8282/provisioning/mgmt/vmc-sddc (referer http://10.244.10.110:8282/provisioning/uerp) as a remote request to change auth context
2021-10-05T04:06:51.975Z [priority='INFO' thread='reactor-http-epoll-13' user='' org='' context='' parent='' token=''] com.vmware.xenon.common.SpringHostUtils.responseEntityToOperation:901 - [POST https://console. cloud.vmware.com/csp/gateway/am/api/auth/api-tokens/authorize] Exception received with no ClientResponse: java.util.concurrent.CompletionException: javax.net.ssl.SSLException: failure when writing TLS control frames
at java.base/java.util.concurrent.CompletableFuture.encodeThrowable(CompletableFuture.java:331)
at java.base/java.util.concurrent.CompletableFuture.completeThrowable(CompletableFuture.java:346)
at java.base/java.util.concurrent.CompletableFuture$UniCompose.tryFire(CompletableFuture.java:1063)
at java.base/java.util.concurrent.CompletableFuture.postComplete(CompletableFuture.java:506)
at java.base/java.util.concurrent.CompletableFuture.completeExceptionally(CompletableFuture.java:2088)
at reactor.core.publisher.MonoToCompletableFuture.onError(MonoToCompletableFuture.java:76)
at io.opentracing.contrib.reactor.TracedSubscriber.onError(TracedSubscriber.java:79)
at reactor.core.publisher.SerializedSubscriber.onError(SerializedSubscriber.java:124)
*
*
*
at io.netty.channel.DefaultChannelPipeline.fireChannelInactive(DefaultChannelPipeline.java:901)
at io.netty.channel.AbstractChannel$AbstractUnsafe$8.run(AbstractChannel.java:818)
at io.netty.util.concurrent.AbstractEventExecutor.safeExecute(AbstractEventExecutor.java:164)
at io.netty.util.concurrent.SingleThreadEventExecutor.runAllTasks(SingleThreadEventExecutor.java:472)
at io.netty.channel.epoll.EpollEventLoop.run(EpollEventLoop.java:384)
at io.netty.util.concurrent.SingleThreadEventExecutor$4.run(SingleThreadEventExecutor.java:989)
at io.netty.util.internal.ThreadExecutorMap$2.run(ThreadExecutorMap.java:74)
at io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30)
at java.base/java.lang.Thread.run(Thread.java:834)
Caused by: javax.net.ssl.SSLException: failure when writing TLS control frames
at io.netty.handler.ssl.SslHandler.setHandshakeFailureTransportFailure(SslHandler.java:1855)
Suppressed: reactor.core.publisher.FluxOnAssembly$OnAssemblyException:
Error has been observed at the following site(s):
|_ checkpoint ⇢ Request to POST https://console.cloud.vmware.com/csp/gateway/am/api/auth/api-tokens/authorize [DefaultWebClient]
Stack trace:
at io.netty.handler.ssl.SslHandler.setHandshakeFailureTransportFailure(SslHandler.java:1855)
at io.netty.handler.ssl.SslHandler.access$600(SslHandler.java:167)
at io.netty.handler.ssl.SslHandler$2.operationComplete(SslHandler.java:970)
at io.netty.handler.ssl.SslHandler$2.operationComplete(SslHandler.java:965)
at io.netty.util.concurrent.DefaultPromise.notifyListener0(DefaultPromise.java:577)
at io.netty.util.concurrent.DefaultPromise.notifyListenersNow(DefaultPromise.java:551)
at io.netty.util.concurrent.DefaultPromise.notifyListeners(DefaultPromise.java:490)
at io.netty.util.concurrent.DefaultPromise.setValue0(DefaultPromise.java:615)*
*
*
*
at io.netty.channel.epoll.EpollEventLoop.run(EpollEventLoop.java:384)
at io.netty.util.concurrent.SingleThreadEventExecutor$4.run(SingleThreadEventExecutor.java:989)
at io.netty.util.internal.ThreadExecutorMap$2.run(ThreadExecutorMap.java:74)
at io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30)
at java.base/java.lang.Thread.run(Thread.java:834)
Caused by: io.netty.handler.proxy.ProxyConnectException: http, none, proxy-service.prelude.svc.cluster.local/10.244.14.224:3128 => console.cloud.vmware.com:443, disconnected
at io.netty.handler.proxy.ProxyHandler.channelInactive(ProxyHandler.java:234)
at io.netty.channel.AbstractChannelHandlerContext.invokeChannelInactive(AbstractChannelHandlerContext.java:262)
*
*
at io.netty.channel.DefaultChannelPipeline.fireChannelInactive(DefaultChannelPipeline.java:901)
at io.netty.channel.AbstractChannel$AbstractUnsafe$8.run(AbstractChannel.java:818)
at io.netty.util.concurrent.AbstractEventExecutor.safeExecute(AbstractEventExecutor.java:164)
at io.netty.util.concurrent.SingleThreadEventExecutor.runAllTasks(SingleThreadEventExecutor.java:472)
at io.netty.channel.epoll.EpollEventLoop.run(EpollEventLoop.java:384)
at io.netty.util.concurrent.SingleThreadEventExecutor$4.run(SingleThreadEventExecutor.java:989)
at io.netty.util.internal.ThreadExecutorMap$2.run(ThreadExecutorMap.java:74)
at io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30)
at java.base/java.lang.Thread.run(Thread.java:834)When this error occurs we see following statements under proxy-service-xxxxx/squid-proxy.log
1633406811.973 epoch timestamp relates to the timestamp when the error occurred in the UI.
1633406811.973 --> 2021-10-05T04:06:51
1633406811.973 240 10.244.0.110 TCP_TUNNEL/407 293 CONNECT console.cloud.vmware.com:443 - FIRSTUP_PARENT/59.154.134.108 -Inspecting older squid-proxy logs, whenever an attempt to add a new VMC vCenter cloud account was done , we did see this statement
proxy-service/squid-proxy.log-202110020000.xz_extracted/squid-proxy.log-202110020000:1633063657.998 108 10.244.10.110 TCP_TUNNEL/407 293 CONNECT console.cloud.vmware.com:443 - FIRSTUP_PARENT/59.154.134.108 -
proxy-service/squid-proxy.log:1633406811.973 240 10.244.10.110 TCP_TUNNEL/407 293 CONNECT console.cloud.vmware.com:443 - FIRSTUP_PARENT/59.154.134.108 -
proxy-service/squid-proxy.log-202110010000.xz_extracted/squid-proxy.log-202110010000:1633008305.662 980 10.244.10.110 TCP_TUNNEL/407 293 CONNECT console.cloud.vmware.com:443 - FIRSTUP_PARENT/59.154.134.108 -
proxy-service/squid-proxy.log-202110010000.xz_extracted/squid-proxy.log-202110010000:1633008582.091 1413 10.244.10.110 TCP_TUNNEL/407 293 CONNECT console.cloud.vmware.com:443 - FIRSTUP_PARENT/59.154.134.108 -
proxy-service/squid-proxy.log-202110010000.xz_extracted/squid-proxy.log-202110010000:1633008851.485 2341 10.244.10.110 TCP_TUNNEL/407 287 CONNECT console.cloud.vmware.com:443 - FIRSTUP_PARENT/59.154.134.109 -
proxy-service/squid-proxy.log-202110010000.xz_extracted/squid-proxy.log-202110010000:1633008862.656 24 10.244.10.110 TCP_TUNNEL/407 287 CONNECT console.cloud.vmware.com:443 - FIRSTUP_PARENT/59.154.134.109 -
Let's understand this squid-proxy statement in depth once
1633406811.973 | The client request time stamp in Squid format |
240 | The time the proxy spent processing the client request; the number of milliseconds between the time that the client established the connection with the proxy and the time that the proxy sent the last byte of the response back to the client. |
10.244.0.110 | The IP address of the client's host machine. In our case it's the provisioning-service-app |
TCP_TUNNEL/407 | Cache Result Code. How the cache responded to the request. The proxy response status code from the content gateway to the client |
293 | The length of the content gateway |
CONNECT | The client request method: GET, POST, and so on |
console.cloud.vmware.com:443 | Canonical URL |
- | The authenticated client's user name. A hyphen (-) means that no authentication was required |
FIRSTUP_PARENT/59.154.134.108 - | The proxy hierarchy route; the route Content Gateway used to retrieve the object. The proxy request server name; the name of the server that fulfilled the request. If the request was a cache hit, this field contains a hyphen (-). |
As we can see all of the result codes are TCP_TUNNEL/407. What do we understand by this based on the search on google
The HTTP 407 Proxy Authentication Required client error status response code indicates that the request has not been applied because it lacks valid authentication credentials for a proxy server that is between the browser and the server that can access the requested resource.
The vracli proxy show output on the node was as below
root@node02[ ~ ]# vracli proxy show
{
"enabled": true,
"host": "proxy-service.prelude.svc.cluster.local",
"java-proxy-exclude": ********",
"java-user": "arun@nc.com",
"password": null,
"port": 3128,
"proxy-exclude": "************",
"scheme": "http",
"upstream_proxy_host": "******.lb.service.dev",
"upstream_proxy_password_encoded": "*CENSORED*",
"upstream_proxy_port": 80,
"upstream_proxy_user_encoded": "arun%40nc.com",
"user": null,
"internal.proxy.config": "*******",
"internal.proxy.config.type": "non-default"
}After we reached this point , one of our peer pointed out that he did recently face an issue where if the java_user is set to UPN and not just a USERNAME , then TCP_TUNNEL/407 will occur
So based on this we decided to reconfigure the proxy which has been already set
root@node02[ ~ ]# vracli proxy show
{
"enabled": true,
"host": "proxy-service.prelude.svc.cluster.local",
"java-proxy-exclude": ********",
"java-user": "arun",
"password": null,
"port": 3128,
"proxy-exclude": "************",
"scheme": "http",
"upstream_proxy_host": "******.lb.service.dev",
"upstream_proxy_password_encoded": "*CENSORED*",
"upstream_proxy_port": 80,
"upstream_proxy_user_encoded": "arun",
"user": null,
"internal.proxy.config": "*******",
"internal.proxy.config.type": "non-default"
}Once we made the change , we were able to validate the API and there were no exceptions
I will try and gather the reason behind why it does not work with UPN and works with USERNAME and update it here.
Yea , if you have a proxy configured and adding a VMware Cloud on AWS endpoint keep this in mind
Comments