1

I have deployed a container in Google Cloud Run. It's an app built in Spring boot and Java.

I have exposed an endpoint(rest controller) to Cloud run container which further invokes a REST api to hit an external endpoint and at that point it fails. I am hitting the exposed endpoint from Postman.

Container is able to listen to incoming requests and even able to connect to Cloud SQL. Problem is - it cant hit an external API.

I even added an outbound rule in firewall to allow all the traffic but no success. Later, tried to turn the logs ON for firewall but no logs were generated.

Would anyone have any idea what could be the issue here ?

Please see the logs below and exception


2021-09-30T14:33:06.955652Z2021-09-30 14:33:06.955 WARN 1 --- [nio-8080-exec-3] io.netty.util.internal.MacAddressUtil : 
Failed to find a usable hardware address from the network interfaces; using random bytes: 61:71:ba:a4:d5:85:ee:11

021-09-30T14:33:08.094246Z2021-09-30 14:33:08.093 DEBUG 1 --- [or-http-epoll-2] r.netty.http.client.HttpClientConnect : [id:93c6dc9b-1, L:/169.... - R:www.homedepot.ca/23.211.51.167:443] Handler is being applied: {uri=https://www.homedepot.ca/ method=GET}


2021-09-30T15:13:41.887524Z org.springframework.web.reactive.function.client.WebClientRequestException: handshake timed out after 10000ms; 
nested exception is io.netty.handler.ssl.SslHandshakeTimeoutException: handshake timed out after 10000ms at 
org.springframework.web.reactive.function.client.ExchangeFunctions$DefaultExchangeFunction.lambda$wrapException$9(ExchangeFunctions.java:141) 
Suppressed: reactor.core.publisher.FluxOnAssembly$OnAssemblyException:

2021-09-30T15:13:41.887759Z at reactor.core.publisher.FluxConcatMap$ConcatMapImmediate.drain(FluxConcatMap.java:414)
2021-09-30T15:13:41.887776Z at reactor.core.publisher.FluxConcatMap$ConcatMapImmediate.onNext(FluxConcatMap.java:251)
2021-09-30T15:13:41.887805Z at reactor.core.publisher.EmitterProcessor.drain(EmitterProcessor.java:491)
2021-09-30T15:13:41.887813Z at reactor.core.publisher.EmitterProcessor.tryEmitNext(EmitterProcessor.java:299)
2021-09-30T15:13:41.887822Z at reactor.core.publisher.SinkManySerialized.tryEmitNext(SinkManySerialized.java:100)
2021-09-30T15:13:41.887859Z at reactor.core.publisher.InternalManySink.emitNext(InternalManySink.java:27)
2021-09-30T15:13:41.887873Z at reactor.core.publisher.FluxRetryWhen$RetryWhenMainSubscriber.onError(FluxRetryWhen.java:190)
2021-09-30T15:13:41.887893Z at reactor.core.publisher.MonoCreate$MonoSink.error(MonoCreate.java:189)
2021-09-30T15:13:41.887903Z at reactor.netty.http.client.HttpClientConnect$MonoHttpConnect$ClientTransportSubscriber.onError(HttpClientConnect.java:304)
2021-09-30T15:13:41.887916Z at reactor.core.publisher.MonoCreate$MonoSink.error(MonoCreate.java:189)
2021-09-30T15:13:41.887934Z at reactor.netty.resources.PooledConnectionProvider$DisposableAcquire.onUncaughtException(PooledConnectionProvider.java:218)
2021-09-30T15:13:41.887958Z at reactor.netty.resources.PooledConnectionProvider$PooledConnection.onUncaughtException(PooledConnectionProvider.java:467)
2021-09-30T15:13:41.887979Z at reactor.netty.channel.ChannelOperationsHandler.exceptionCaught(ChannelOperationsHandler.java:129)
2021-09-30T15:13:41.887993Z at io.netty.channel.AbstractChannelHandlerContext.invokeExceptionCaught(AbstractChannelHandlerContext.java:302)
2021-09-30T15:13:41.888011Z at io.netty.channel.AbstractChannelHandlerContext.invokeExceptionCaught(AbstractChannelHandlerContext.java:281)
2021-09-30T15:13:41.888032Z at io.netty.channel.AbstractChannelHandlerContext.fireExceptionCaught(AbstractChannelHandlerContext.java:273)
2021-09-30T15:13:41.888049Z at io.netty.channel.CombinedChannelDuplexHandler$DelegatingChannelHandlerContext.fireExceptionCaught(CombinedChannelDuplexHandler.java:424)
2021-09-30T15:13:41.982305Z at io.netty.channel.ChannelHandlerAdapter.exceptionCaught(ChannelHandlerAdapter.java:92)
2021-09-30T15:13:41.982894Z2021-09-30 15:13:41.281 WARN 1 --- [or-http-epoll-3] r.netty.http.client.HttpClientConnect : [id:c351aec9, L:/169.... - R:www.homedepot.ca/96.7.86.161:443] The connection observed an error

enter image description here

Code in Spring boot that is making the call

WebClient webClient =
      WebClient.builder()
          .defaultHeader(HttpHeaders.CONTENT_TYPE, MediaType.APPLICATION_JSON_VALUE)
          .build();
  Mono<HDCanadaProdResp> webClientResponse =
      webClient.get().uri(stockApiurl).retrieve().bodyToMono(HDCanadaProdResp.class);
webClientResponse.block();

All the code works in local system in a Docker Container, not sure what's the issue on Cloud run.

Here is the Dockerfile


FROM maven:3.6.3-openjdk-11-slim as builder

WORKDIR /app
COPY pom.xml .
RUN mvn dependency:go-offline

COPY src/ /app/src/
RUN mvn package -DskipTests


FROM openjdk:11-jre-slim

COPY --from=builder /app/target/*.jar /app.jar

#PORT for cloud run, coz cloud maps to this port
ENV PORT 8080
ENV HOST 0.0.0.0

CMD ["java", "-jar", "/app.jar"]

Update on Nov 7, 2021

I changed my spring Boot code where I was using WebClient API to make rest call and now the error has changed.

old code

 WebClient webClient =
        WebClient.builder()
            .defaultHeader(HttpHeaders.CONTENT_TYPE, MediaType.APPLICATION_JSON_VALUE)
            
            .defaultHeader(HttpHeaders.ACCEPT_ENCODING, "gzip, deflate, br")
            .defaultHeader(HttpHeaders.ACCEPT_LANGUAGE, "en-CA,en-US;q=0.7,en;q=0.3")
            .defaultHeader(HttpHeaders.HOST, "www.homedepot.ca")

            .build();
    Mono<HDCanadaRecomProdResp> webClientResponse =
        webClient.get().uri(prodApiurl).retrieve().bodyToMono(HDCanadaRecomProdResp.class);

    return webClientResponse.block();

New code

 HttpComponentsClientHttpRequestFactory requestFactory =
        new HttpComponentsClientHttpRequestFactory();
    requestFactory.setConnectTimeout(60 * 1000);
    requestFactory.setReadTimeout(60 * 1000);

    RestTemplate restTemplate = new RestTemplate(requestFactory);
    ResponseEntity<HDCanadaRecomProdResp> response = null;
    try {
      HttpHeaders headers = new HttpHeaders();

      headers.setContentType(MediaType.APPLICATION_JSON);
      headers.set(HttpHeaders.ACCEPT_ENCODING, "gzip, deflate, br");
      headers.set(HttpHeaders.ACCEPT_LANGUAGE, "en-CA,en-US;q=0.7,en;q=0.3");
      headers.set(HttpHeaders.HOST, "www.homedepot.ca");
      headers.setAccept(Arrays.asList(MediaType.ALL));


      HttpEntity<Map<String, String>> entity = new HttpEntity<>(headers);
      
      response =
      restTemplate.exchange(prodApiurl, HttpMethod.GET, entity, HDCanadaRecomProdResp.class);
  }

And now the error has changed to

org.springframework.web.client.ResourceAccessException: I/O error on GET request for "https://www.homedepot.ca/api/rec/v1/recommendations/fbt/products/1001200972/store/7301": 
Read timed out; nested exception is java.net.SocketTimeoutException: Read timed out at 
org.springframework.web.client.RestTemplate.doExecute(RestTemplate.java:785) at 
org.springframework.web.client.RestTemplate.execute(RestTemplate.java:711) at 
org.springframework.web.client.RestTemplate.exchange(RestTemplate.java:602) at 
com.pricetracker.productfetcher.client.HomeDepotCAClient.getProductDetails(HomeDepotCAClient.java:68) at 
com.pricetracker.productfetcher.client.HomeDepotCAClient.getProductDetails(HomeDepotCAClient.java:24) at 
com.pricetracker.productfetcher.service.ProductSearchServiceImpl.getProductFromWS(ProductSearchServiceImpl.java:116) at 
com.pricetracker.productfetcher.service.ProductSearchServiceImpl.getProduct(ProductSearchServiceImpl.java:82) at 
com.pricetracker.productfetcher.service.ProductSearchServiceImpl.productSearch(ProductSearchServiceImpl.java:61) at 
com.pricetracker.productfetcher.controller.ProductsController.searchProduct(ProductsController.java:51) at 
com.pricetracker.productfetcher.controller.ProductsController$$FastClassBySpringCGLIB$$37eced0e.invoke(<generated>) at 
org.springframework.cglib.proxy.MethodProxy.invoke(MethodProxy.java:218) at 
org.springframework.aop.framework.CglibAopProxy$CglibMethodInvocation.invokeJoinpoint(CglibAopProxy.java:779) at 
org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:163) at 
org.springframework.aop.framework.CglibAopProxy$CglibMethodInvocation.proceed(CglibAopProxy.java:750) at 
org.springframework.validation.beanvalidation.MethodValidationInterceptor.invoke(MethodValidationInterceptor.java:123) at 
org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:186) at 
org.springframework.aop.framework.CglibAopProxy$CglibMethodInvocation.proceed(CglibAopProxy.java:750) at 
org.springframework.aop.framework.CglibAopProxy$DynamicAdvisedInterceptor.intercept(CglibAopProxy.java:692) at 
com.pricetracker.productfetcher.controller.ProductsController$$EnhancerBySpringCGLIB$$ec439be9.searchProduct(<generated>) at 
java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method) at 
java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(Unknown Source) at 
java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(Unknown Source) at 
java.base/java.lang.reflect.Method.invoke(Unknown Source) at org.springframework.web.method.support.InvocableHandlerMethod.doInvoke(InvocableHandlerMethod.java:197) at 
org.springframework.web.method.support.InvocableHandlerMethod.invokeForRequest(InvocableHandlerMethod.java:141) at 
org.springframework.web.servlet.mvc.method.annotation.ServletInvocableHandlerMethod.invokeAndHandle(ServletInvocableHandlerMethod.java:106) at 
org.springframework.web.servlet.mvc.method.annotation.RequestMappingHandlerAdapter.invokeHandlerMethod(RequestMappingHandlerAdapter.java:895) at 
org.springframework.web.servlet.mvc.method.annotation.RequestMappingHandlerAdapter.handleInternal(RequestMappingHandlerAdapter.java:808) at 
org.springframework.web.servlet.mvc.method.AbstractHandlerMethodAdapter.handle(AbstractHandlerMethodAdapter.java:87) at 
org.springframework.web.servlet.DispatcherServlet.doDispatch(DispatcherServlet.java:1064) at 
org.springframework.web.servlet.DispatcherServlet.doService(DispatcherServlet.java:963) at 

jammer
  • 151
  • 3
  • 23
  • The last-but-one log line is curious .... "failed to find a usable hardware address" is curious. If the server is unable to determine the host machine's IP, outbound calls will fail (because there's no way for the response to be returned). – DazWilkin Sep 30 '21 at 15:57
  • Including images is discouraged on stackoverflow for multiple reasons including making it difficult for others to reference content. Please copy-and-paste text rather than include images when possible. – DazWilkin Sep 30 '21 at 15:58
  • Firewall rules don't apply to Cloud Run services in this case. – DazWilkin Sep 30 '21 at 16:00
  • @DazWilkin : I removed the image of logs and added text. – jammer Sep 30 '21 at 16:19
  • @DazWilkin "failed to find a usable hardware address" : after googling for this log, didn't find anything that could cause the issue here – jammer Sep 30 '21 at 16:20
  • I now see another error `SslHandshakeTimeoutException`. Your app is failing to make a TLS connection. This can sometimes result from building a container that lacks certs. Please include your Dockerfile. – DazWilkin Sep 30 '21 at 18:28
  • Do you have a serverless VPC connector? – guillaume blaquiere Sep 30 '21 at 20:03
  • @DazWilkin I just added my Dockerfile. Just to add, this same dockerfile runs in my local system. – jammer Oct 01 '21 at 00:23
  • @guillaumeblaquiere - No, I am not using a serverless VPC connector. – jammer Oct 01 '21 at 00:23
  • Hmm, that it runs locally is interesting. However I've experienced before that a container that runs locally didn't run on Cloud Run (that case was caused by an Ubuntu version change). I wonder whether you could enumerate the environment? It would be interesting to see whether there are unexpected differences. How difficult to switch to a pure OS (`FROM:debian`) with a JDK or just JRE? – DazWilkin Oct 01 '21 at 01:00
  • Out of left field: I wonder whether this is somehow related to the Lets Encrypt ticket expiry? Has this ever worked? If it stopped today... – DazWilkin Oct 01 '21 at 04:05
  • @DazWilkin Sorry didnt get your last question. Docker container is working in local system. – jammer Oct 04 '21 at 13:16
  • Is your issue resolved @jammer – Priyashree Bhadra Oct 11 '21 at 17:18
  • @PriyashreeBhadra Sadly No. Looks like I have to see another option like deploying/setup on VM. – jammer Oct 12 '21 at 18:28
  • Can you use [strace](https://cloud.google.com/run/docs/troubleshooting/tracing-system-calls) and let me know the log output? Also view the [logs](https://cloud.google.com/run/docs/troubleshooting?utm_campaign=CDR_ahm_aap-severless_cloud-run-faq_&utm_source=external&utm_medium=web#sandbox) in the Cloud Logging section of the GCP Console (not in the "Logs" tab of the Cloud Run section), you can look for "Container Sandbox" with a "DEBUG" severity in the varlog/system logs. – Priyashree Bhadra Oct 18 '21 at 01:45
  • @PriyashreeBhadra The java application is running in Docker and deployed in Cloud run. I am not sure how to use strace here. I checked GCP console logging and didnt see any log with DEBUG severity under varlog/system logs for "Container Sandbox". Meanwhile I made some changes in spring code, earlier I was using Webclient API for making Rest calls, now I switched to RestTemplate.exchange and the error has changed. I am updating my question with this. – jammer Nov 07 '21 at 05:54
  • @PriyashreeBhadra I just checked my logs again, I see this log(which wasnt visible earlier, as it was coming during startup of container) Debug 2021-11-07T12:39:14.876726806ZContainer Sandbox: Unsupported syscall setsockopt(0xa,0x11,0x67,0x3ed0ac62bffc,0x4,0x1a). It is very likely that you can safely ignore this message and that this is not the cause of any error you might be troubleshooting. Please, refer to https://gvisor.dev/docs/user_guide/compatibility/linux/amd64/setsockopt for more information. – jammer Nov 07 '21 at 12:59
  • Okay now I would want you to try running your application locally on Docker using these [instructions](https://cloud.google.com/run/docs/testing/local) and verify if your applications boots fine locally?Also the container must listen for requests on 0.0.0.0 on the port to which requests are sent. By default, requests are sent to 8080. Add the --min-instances in cloudbuild.yaml file and give it some value for now and then try. – Priyashree Bhadra Nov 08 '21 at 12:02
  • @PriyashreeBhadra I am already running the Docker locally and went ahead with the instructions to add --min-instances. docker run -d -p 8080:8080 -v "c:\GIT_Personal\my-sa.json":/opt/app/my-sa.json -e GOOGLE_APPLICATION_CREDENTIALS=/opt/app/my-sa.json pricetracker-productfetcher #Cloudbld - name: 'gcr.io/google.com/cloudsdktool/cloud-sdk' entrypoint: gcloud args: - 'run' - 'deploy' - '${_SERVICE_NAME}' - '--image' - 'gcr.io/${_PROJECT_ID}/${_GITHUB}/${_SERVICE_NAME}:$COMMIT_SHA' - '--region' - 'us-central1' - '--min-instances=1' – jammer Nov 09 '21 at 15:20
  • Great! So you are able to run it locally. That means there is no issue with the docker image or your configurations.Unsupported syscall- This message indicates that system calls may not be supported in this Cloud Run(fully managed) as container instances are sandboxed using the gVisor container runtime sandbox. Its a known issue in Cloud Run fully managed. You can try [Cloud Run for Anthos](https://cloud.google.com/anthos/run/docs/setup) with same configurations and container setup(with less allocated resources) – Priyashree Bhadra Nov 10 '21 at 08:11
  • See [socket(7) - Linux manual page 8](https://man7.org/linux/man-pages/man7/socket.7.html) for details. So gvisor does not support this socket option. Have a look at this [Github issue](https://github.com/google/gvisor/issues/1739) which talks about the same error message you received. – Priyashree Bhadra Nov 10 '21 at 08:18
  • Please complete the entire setup with Cloud Run for Anthos. If we are successful, we would atleast know, it was sandbox issue on Cloud Run (fully managed). Give it a try and let me know if it worked. – Priyashree Bhadra Nov 10 '21 at 08:27
  • 1
    @PriyashreeBhadra I was traveling so couldn't try it. But I looked at the Cloud Anthos, I need to set up that now which I would say will be a different path than Cloud Run. – jammer Dec 06 '21 at 14:57

1 Answers1

0

Use strace for this kind of Cloud Run related issues. Also view the logs in the Cloud Logging section of the GCP Console (not in the "Logs'' tab of the Cloud Run section), you can look for "Container Sandbox" with a "DEBUG" severity in the varlog/system logs. Also try running your application locally on Docker using these instructions and verify if your applications boots fine locally. The container must listen for requests on 0.0.0.0 on the port to which requests are sent. By default, requests are sent to 8080. Add the --min-instances in cloudbuild.yaml file and give it some value for now and then try.

If you see this log (which was not visible earlier, as it was coming during startup of container) Debug 2021-11-07T12:39:14.876726806ZContainer Sandbox: Unsupported syscall setsockopt(0xa,0x11,0x67,0x3ed0ac62bffc,0x4,0x1a) and you are able to run the setup locally, that means there is no issue with the docker image or your configurations. Unsupported syscall- This message indicates that system calls may not be supported in this Cloud Run (fully managed) as container instances are sandboxed using the gVisor container runtime sandbox.
See socket(7) - Linux manual page 8 for details. So gvisor does not support this socket option. Have a look at this Github issue which talks about the same error message you received.

It's a known issue in Cloud Run fully managed. You can try Cloud Run for Anthos with the same configurations and container setup (with less allocated resources).

Priyashree Bhadra
  • 3,182
  • 6
  • 23