Cloud Run app responds with "503 Service Unavailable" when using Micronaut HTTP Client

1

My application is based on Micronaut and GraalVM (java 11) and does a simple call to http://httpbin.org/get:

@Controller("/api")
class HelloWorld(
    @Client("http://httpbin.org")
    private val httpClient: RxHttpClient
) {
    private val logger = LoggerFactory.getLogger(javaClass)

    @Get("/hello")
    fun hello(): String {
        return "Hello World!"
    }

    @Get("/fb")
    fun fb(): Flowable<String> {
        logger.info("Trying to call FB")
        logger.info("Using url http://httpbin.org/get")
        try {
            return httpClient.retrieve("/get")
                .doOnError { logger.error("Error calling fb api flowable", it) }
                .doFinally { logger.info("Finished calling FB api flowable") }
        } catch (ex: Exception) {
            logger.error("Error calling fb api", ex)
            throw ex
        } finally {
            logger.info("Finished calling fb api")
        }
    }
}

When I build a docker image of the app using this Dockerfile:

FROM maven:3.6.3-jdk-11 as maven
COPY . /home/app
WORKDIR /home/app
RUN mvn package

FROM oracle/graalvm-ce:19.3.1-java11 as graalvm
COPY --from=maven /home/app/target/app-*.jar /home/app/
WORKDIR /home/app
RUN gu install native-image
RUN native-image --no-server --enable-http --enable-https -cp app-*.jar

FROM debian:stretch
EXPOSE 8080
COPY --from=graalvm /home/app/app .
#RUN apt-get update && apt-get -y install strace
ENTRYPOINT ["./app"]

Everything works in my local environment. But when I push the image to Google Cloud Repository, deploy it to Cloud Run and try to access the endpoint /api/fb, it crashes the container with 503 Service Unavailable.

The error in the logs is "The request failed because the HTTP connection to the instance had an error.". When I enable strace, these are the logs:

A 2020-02-07T12:04:27.443115Z [pid    18] <... futex resumed> )       = -1 ETIMEDOUT (Connection timed out) 
A 2020-02-07T12:04:27.443125Z [pid    18] futex(0x3e61dc018a80, FUTEX_WAKE_PRIVATE, 1) = 0 
A 2020-02-07T12:04:27.443357Z [pid    18] futex(0x3e62040009c4, FUTEX_CMP_REQUEUE_PRIVATE, 1, 2147483647, 0x3e6204000990, 234) = 1 
A 2020-02-07T12:04:27.443369Z [pid    15] <... futex resumed> )       = 0 
A 2020-02-07T12:04:27.443440Z [pid    18] futex(0x3e61dc018ab4, FUTEX_WAIT_BITSET_PRIVATE, 157, {tv_sec=3624, tv_nsec=391761056}, 0xffffffff <unfinished ...> 
A 2020-02-07T12:04:27.443478Z [pid    15] futex(0x3e6204000990, FUTEX_WAKE_PRIVATE, 1) = 0 
A 2020-02-07T12:04:27.959629Z [pid    20] epoll_wait(17,  <unfinished ...> 
A 2020-02-07T12:04:27.959658Z [pid     8] <... epoll_wait resumed> [{EPOLLIN, {u32=53, u64=53}}], 1024, -1) = 1 
A 2020-02-07T12:04:27.959865Z [pid     8] accept(53, {sa_family=AF_INET6, sin6_port=htons(36294), inet_pton(AF_INET6, "::ffff:169.254.8.129", &sin6_addr), sin6_flowinfo=htonl(0), sin6_scope_id=0}, [28]) = 4 
A 2020-02-07T12:04:27.959884Z [pid     8] fcntl(4, F_GETFL)           = 0x2 (flags O_RDWR) 
A 2020-02-07T12:04:27.959945Z [pid     8] getsockname(4, {sa_family=AF_INET6, sin6_port=htons(8080), inet_pton(AF_INET6, "::ffff:169.254.8.130", &sin6_addr), sin6_flowinfo=htonl(0), sin6_scope_id=0}, [28]) = 0 
A 2020-02-07T12:04:27.960036Z [pid     8] getsockname(4, {sa_family=AF_INET6, sin6_port=htons(8080), inet_pton(AF_INET6, "::ffff:169.254.8.130", &sin6_addr), sin6_flowinfo=htonl(0), sin6_scope_id=0}, [28]) = 0 
A 2020-02-07T12:04:27.960085Z [pid     8] fcntl(4, F_GETFL)           = 0x2 (flags O_RDWR) 
A 2020-02-07T12:04:27.960128Z [pid     8] fcntl(4, F_SETFL, O_RDWR|O_NONBLOCK) = 0 
A 2020-02-07T12:04:27.960211Z [pid     8] setsockopt(4, SOL_TCP, TCP_NODELAY, [1], 4) = 0 
A 2020-02-07T12:04:27.960322Z [pid     8] getsockopt(4, SOL_SOCKET, SO_SNDBUF, [1048576], [4]) = 0 
A 2020-02-07T12:04:27.960440Z [pid     8] mmap(NULL, 8392704, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS|MAP_STACK, -1, 0) = 0x3e60f0e00000 
A 2020-02-07T12:04:27.960564Z [pid     8] mprotect(0x3e60f0e00000, 4096, PROT_NONE) = 0 
A 2020-02-07T12:04:27.960793Z [pid     8] clone(/usr/bin/strace: Process 22 attached 
A 2020-02-07T12:04:27.960875Z  <unfinished ...> 
A 2020-02-07T12:04:27.965711Z [pid    22] set_robust_list(0x3e60f16009e0, 24 <unfinished ...> 
A 2020-02-07T12:04:27.965738Z [pid     8] <... clone resumed> child_stack=0x3e60f15fffb0, flags=CLONE_VM|CLONE_FS|CLONE_FILES|CLONE_SIGHAND|CLONE_THREAD|CLONE_SYSVSEM|CLONE_SETTLS|CLONE_PARENT_SETTID|CLONE_CHILD_CLEARTID, parent_tidptr=0x3e60f16009d0, tls=0x3e60f1600700, child_tidptr=0x3e60f16009d0) = 22 
A 2020-02-07T12:04:27.965753Z [pid    22] <... set_robust_list resumed> ) = -1 ENOSYS (Function not implemented) 
A 2020-02-07T12:04:27.965761Z [pid     8] epoll_wait(29,  <unfinished ...> 
A 2020-02-07T12:04:27.965770Z [pid    22] sched_getaffinity(22, 32, [0, 1]) = 8 
A 2020-02-07T12:04:27.965783Z [pid    22] futex(0x3b4c0c4, FUTEX_CMP_REQUEUE_PRIVATE, 1, 2147483647, 0x3b4c068, 30) = 1 
A 2020-02-07T12:04:27.965790Z [pid     3] <... futex resumed> )       = 0 
A 2020-02-07T12:04:27.965799Z [pid     3] futex(0x3b4c068, FUTEX_WAIT_PRIVATE, 2, NULL <unfinished ...> 
A 2020-02-07T12:04:27.965807Z [pid    22] futex(0x3b4c068, FUTEX_WAKE_PRIVATE, 1) = 1 
A 2020-02-07T12:04:27.965816Z [pid    22] mmap(NULL, 2097152, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0 <unfinished ...> 
A 2020-02-07T12:04:27.965824Z [pid     3] <... futex resumed> )       = 0 
A 2020-02-07T12:04:27.965833Z [pid     3] futex(0x3b4c068, FUTEX_WAKE_PRIVATE, 1 <unfinished ...> 
A 2020-02-07T12:04:27.965842Z [pid    22] <... mmap resumed> )        = 0x3e60f0c00000 
A 2020-02-07T12:04:27.965850Z [pid     3] <... futex resumed> )       = 0 
A 2020-02-07T12:04:27.965858Z [pid     3] futex(0x3b4c0c4, FUTEX_WAIT_PRIVATE, 31, NULL <unfinished ...> 
A 2020-02-07T12:04:27.965866Z [pid    22] munmap(0x3e60f0d00000, 1048576) = 0 
A 2020-02-07T12:04:27.965874Z [pid    22] prctl(PR_SET_NAME, "ntLoopGroup-1-7"...) = 0 
A 2020-02-07T12:04:27.965882Z [pid    22] epoll_wait(20, [], 1024, 0) = 0 
A 2020-02-07T12:04:27.965891Z [pid    22] mmap(NULL, 2097152, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x3e60f0a00000 
A 2020-02-07T12:04:27.965903Z [pid    22] munmap(0x3e60f0b00000, 1048576) = 0 
A 2020-02-07T12:04:27.966731Z [pid    22] epoll_ctl(20, EPOLL_CTL_ADD, 4, {EPOLLIN, {u32=4, u64=4}}) = 0 
A 2020-02-07T12:04:27.966836Z [pid    22] epoll_wait(20, [{EPOLLIN, {u32=4, u64=4}}], 1024, 299996) = 1 
A 2020-02-07T12:04:27.967306Z [pid    22] mmap(NULL, 2097152, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x3e60f0800000 
A 2020-02-07T12:04:27.967325Z [pid    22] munmap(0x3e60f0900000, 1048576) = 0 
A 2020-02-07T12:04:27.967493Z [pid    22] mmap(NULL, 16781312, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x3e60ef600000 
A 2020-02-07T12:04:27.984977Z [pid    22] read(4, "GET /api/fb HTTP/1.1\r\nhost: app"..., 1024) = 864 
A 2020-02-07T12:04:27.985474Z [36m12:04:27.985[0;39m [1;30m[nioEventLoopGroup-1-7][0;39m [34mINFO [0;39m [35mcom.roihunter.app.HelloWorld[0;39m - Trying to call FB 
A 2020-02-07T12:04:27.985581Z [36m12:04:27.985[0;39m [1;30m[nioEventLoopGroup-1-7][0;39m [34mINFO [0;39m [35mcom.roihunter.app.HelloWorld[0;39m - Using url /act_984750788289990/insights 
A 2020-02-07T12:04:27.985645Z [pid    22] write(1, "\33[36m12:04:27.985\33[0;39m \33[1;30m"..., 143) = 143 
A 2020-02-07T12:04:27.985666Z [pid    22] write(1, "\33[36m12:04:27.985\33[0;39m \33[1;30m"..., 165) = 165 
A 2020-02-07T12:04:27.985766Z [36m12:04:27.985[0;39m [1;30m[nioEventLoopGroup-1-7][0;39m [34mINFO [0;39m [35mcom.roihunter.app.HelloWorld[0;39m - Finished calling fb api 
A 2020-02-07T12:04:27.985836Z [pid    22] write(1, "\33[36m12:04:27.985\33[0;39m \33[1;30m"..., 149) = 149 
A 2020-02-07T12:04:27.986363Z [pid    22] write(4, "HTTP/1.1 200 OK\r\ntransfer-encodi"..., 143) = 143 
E 2020-02-07T12:04:27.988626Z GET 503 546 B 31 ms curl/7.66.0 https://app-5phkf6s3jq-ez.a.run.app/api/fb GET 503 546 B 31 ms curl/7.66.0 
A 2020-02-07T12:04:27.989104Z [pid    22] writev(4, [{iov_base="1\r\n", iov_len=3}, {iov_base="[", iov_len=1}, {iov_base="\r\n", iov_len=2}], 3) = 6 
A 2020-02-07T12:04:27.989513Z [pid    22] mmap(NULL, 8392704, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS|MAP_STACK, -1, 0) = 0x3e60eec00000 
A 2020-02-07T12:04:27.989534Z [pid    22] mprotect(0x3e60eec00000, 4096, PROT_NONE) = 0 
A 2020-02-07T12:04:27.989732Z [pid    22] clone(/usr/bin/strace: Process 23 attached 
A 2020-02-07T12:04:27.989753Z  <unfinished ...> 
A 2020-02-07T12:04:27.989873Z [pid    23] set_robust_list(0x3e60ef4009e0, 24) = -1 ENOSYS (Function not implemented) 
A 2020-02-07T12:04:27.989884Z [pid    23] sched_getaffinity(23, 32, [0, 1]) = 8 
A 2020-02-07T12:04:27.989964Z [pid    23] futex(0x3b4c0c4, FUTEX_CMP_REQUEUE_PRIVATE, 1, 2147483647, 0x3b4c068, 32) = 1 
A 2020-02-07T12:04:27.990286Z [pid    23] mmap(NULL, 2097152, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0 <unfinished ...> 
A 2020-02-07T12:04:27.990303Z [pid    22] <... clone resumed> child_stack=0x3e60ef3fffb0, flags=CLONE_VM|CLONE_FS|CLONE_FILES|CLONE_SIGHAND|CLONE_THREAD|CLONE_SYSVSEM|CLONE_SETTLS|CLONE_PARENT_SETTID|CLONE_CHILD_CLEARTID, parent_tidptr=0x3e60ef4009d0, tls=0x3e60ef400700, child_tidptr=0x3e60ef4009d0) = 23 
A 2020-02-07T12:04:27.990311Z [pid    23] <... mmap resumed> )        = 0x3e60eea00000 
A 2020-02-07T12:04:27.990320Z [pid     3] <... futex resumed> )       = 0 
A 2020-02-07T12:04:27.990327Z [pid     3] futex(0x3b4c068, FUTEX_WAKE_PRIVATE, 1) = 0 
A 2020-02-07T12:04:27.990335Z [pid     3] futex(0x3b4c0c4, FUTEX_WAIT_PRIVATE, 33, NULL <unfinished ...> 
A 2020-02-07T12:04:27.990345Z [pid    23] munmap(0x3e60eeb00000, 1048576) = 0 
A 2020-02-07T12:04:27.990423Z [pid    22] socket(AF_INET6, SOCK_STREAM, IPPROTO_IP <unfinished ...> 
A 2020-02-07T12:04:27.990435Z [pid    23] prctl(PR_SET_NAME, "ionThreadPool-1"... <unfinished ...> 
A 2020-02-07T12:04:27.990446Z [pid    22] <... socket resumed> )      = 80 
A 2020-02-07T12:04:27.990668Z [pid    22] setsockopt(80, SOL_IPV6, IPV6_V6ONLY, [0], 4) = 0 
A 2020-02-07T12:04:27.990684Z [pid    23] <... prctl resumed> )       = 0 

I tried using a different library to make the call, Java 11 Http client, and it works. But whatever I do, it doesn't work when I use Micronaut Http client, and there is no helpful message.

I also tried using Java 8, a different linux distribution in the docker image (fedora:latest, ubuntu:latest), but it didn't help.

Do you have any idea what could be causing this?

Thanks for you answer in advance.

kotlin
micronaut
google-cloud-run
graalvm
micronaut-client
asked on Stack Overflow Feb 7, 2020 by VaclavDedik • edited Feb 7, 2020 by VaclavDedik

1 Answer

0

So it looks like the core of the issue is that Cloud Run currently does not support HTTP streaming:

https://cloud.google.com/run/docs/issues#grpc_websocket

And when I return Flowable with Micronauts, it is opening a streamable HTTP connection. So the solution is not to use Flowable (or any other Publisher that is unbounded e.g. Flow, Flux etc) as a response.

answered on Stack Overflow Feb 12, 2020 by VaclavDedik • edited Feb 12, 2020 by VaclavDedik

User contributions licensed under CC BY-SA 3.0