search

gravitee-io / issues

Gravitee.io - API Platform - Issues
64 stars 26 forks source link

After gateway timeout, Gravitee Gateway is not handling http requests #9086

Closed meveno closed 3 months ago

meveno commented 1 year ago

Describe the bug

describe-the-bug

After a timeout, the gateway is unavailable (it doesn't serve requests) and we see this exception repeatidly in the log :

io.vertx.core.http.impl.NoStackTraceTimeoutException: The timeout period of 10000ms has been exceeded while executing GET / for server rec-annuaire-postgrest-api.postgrest-api.svc.cluster.local:3000 12:30:25.468 [vert.x-eventloop-thread-1] [] ERROR io.vertx.core.impl.ContextImpl - Unhandled exception java.lang.NullPointerException: Cannot invoke "io.vertx.core.http.HttpClientRequest.headers()" because "this.httpClientRequest" is null at io.gravitee.connector.http.HttpConnection.lambda$writeUpstreamHeaders$6(HttpConnection.java:324) at java.base/java.lang.Iterable.forEach(Unknown Source) at io.gravitee.connector.http.HttpConnection.writeUpstreamHeaders(HttpConnection.java:323) at io.gravitee.connector.http.HttpConnection.writeHeaders(HttpConnection.java:300) at io.gravitee.connector.http.HttpConnection.write(HttpConnection.java:280) at io.gravitee.connector.http.HttpConnection.write(HttpConnection.java:50) at io.gravitee.gateway.core.endpoint.factory.impl.EndpointFactoryImpl$ConnectorProxyConnection.write(EndpointFactoryImpl.java:120) at io.gravitee.gateway.core.endpoint.factory.impl.EndpointFactoryImpl$ConnectorProxyConnection.write(EndpointFactoryImpl.java:74) at io.gravitee.gateway.core.logging.LoggableProxyConnection.write(LoggableProxyConnection.java:104) at io.gravitee.gateway.core.logging.LoggableProxyConnection.write(LoggableProxyConnection.java:39) at io.gravitee.gateway.core.invoker.EndpointInvoker.lambda$invoke$2(EndpointInvoker.java:79) at io.gravitee.gateway.core.processor.chain.AbstractStreamableProcessorChain.lambda$handle$5(AbstractStreamableProcessorChain.java:70) at io.gravitee.gateway.core.processor.EmptyStreamableProcessor.write(EmptyStreamableProcessor.java:47) at io.gravitee.gateway.core.processor.chain.AbstractStreamableProcessorChain.lambda$handle$5(AbstractStreamableProcessorChain.java:70) at io.gravitee.gateway.policy.impl.StreamablePolicyChain.write(StreamablePolicyChain.java:120) at io.gravitee.gateway.policy.impl.StreamablePolicyChain.write(StreamablePolicyChain.java:35) at io.gravitee.gateway.core.processor.chain.AbstractStreamableProcessorChain.write(AbstractStreamableProcessorChain.java:99) at io.gravitee.gateway.core.processor.StreamableProcessorDecorator.write(StreamableProcessorDecorator.java:74) at io.gravitee.gateway.policy.impl.StreamablePolicyChain.write(StreamablePolicyChain.java:120) at io.gravitee.gateway.policy.impl.StreamablePolicyChain.write(StreamablePolicyChain.java:35) at io.gravitee.gateway.core.processor.StreamableProcessorDecorator.write(StreamableProcessorDecorator.java:74) at io.gravitee.gateway.core.processor.EmptyStreamableProcessor.write(EmptyStreamableProcessor.java:47) at io.gravitee.gateway.core.processor.chain.AbstractStreamableProcessorChain.write(AbstractStreamableProcessorChain.java:99) at io.gravitee.gateway.core.logging.LoggableClientRequest.lambda$bodyHandler$0(LoggableClientRequest.java:68) at io.gravitee.gateway.http.vertx.VertxHttpServerRequest.lambda$bodyHandler$0(VertxHttpServerRequest.java:187) at io.vertx.core.impl.AbstractContext.dispatch(AbstractContext.java:100) at io.vertx.core.http.impl.HttpEventHandler.handleChunk(HttpEventHandler.java:51) at io.vertx.core.http.impl.Http1xServerRequest.onData(Http1xServerRequest.java:531) at io.vertx.core.http.impl.Http1xServerRequest.lambda$pendingQueue$1(Http1xServerRequest.java:128) at io.vertx.core.streams.impl.InboundBuffer.handleEvent(InboundBuffer.java:240) at io.vertx.core.streams.impl.InboundBuffer.drain(InboundBuffer.java:227) at io.vertx.core.streams.impl.InboundBuffer.lambda$fetch$0(InboundBuffer.java:280) at io.vertx.core.impl.AbstractContext.dispatch(AbstractContext.java:100) at io.vertx.core.impl.AbstractContext.dispatch(AbstractContext.java:63) at io.vertx.core.impl.EventLoopContext.lambda$runOnContext$0(EventLoopContext.java:38) at io.netty.util.concurrent.AbstractEventExecutor.safeExecute(AbstractEventExecutor.java:164) at io.netty.util.concurrent.SingleThreadEventExecutor.runAllTasks(SingleThreadEventExecutor.java:469) at io.netty.channel.epoll.EpollEventLoop.run(EpollEventLoop.java:384) at io.netty.util.concurrent.SingleThreadEventExecutor$4.run(SingleThreadEventExecutor.java:986) 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(Unknown Source)

Expected behaviour

expected-behaviour

The gateway is serving request or at least the healthcheck is ko so the kube scheduler is not restarting the pod...

Environment

environment

Gravitee docker image : graviteeio/apim-gateway:3.20.10

Potential impacts

potential-impacts

Gateway does not serve requests.

stale[bot] commented 10 months ago

This issue has been automatically marked as stale because it has not had recent activity. It will be closed if no further activity occurs. Thank you for your contributions.

meveno commented 9 months ago

It seems fixed in the latest gravitee gateway version.

meveno commented 9 months ago

Bad news, We are still having this exception :(

Docker image : graviteeio/apim-gateway:3.20.10

16:15:34.221 [vert.x-eventloop-thread-3] [] ERROR io.vertx.core.impl.ContextImpl - Unhandled exception
java.lang.NullPointerException: Cannot invoke "io.vertx.core.http.HttpClientRequest.headers()" because "this.httpClientRequest" is null
    at io.gravitee.connector.http.HttpConnection.lambda$writeUpstreamHeaders$6(HttpConnection.java:324)
    at java.base/java.lang.Iterable.forEach(Unknown Source)
    at io.gravitee.connector.http.HttpConnection.writeUpstreamHeaders(HttpConnection.java:323)
    at io.gravitee.connector.http.HttpConnection.writeHeaders(HttpConnection.java:300)
    at io.gravitee.connector.http.HttpConnection.write(HttpConnection.java:280)
    at io.gravitee.connector.http.HttpConnection.write(HttpConnection.java:50)
    at io.gravitee.gateway.core.endpoint.factory.impl.EndpointFactoryImpl$ConnectorProxyConnection.write(EndpointFactoryImpl.java:120)
    at io.gravitee.gateway.core.endpoint.factory.impl.EndpointFactoryImpl$ConnectorProxyConnection.write(EndpointFactoryImpl.java:74)
    at io.gravitee.gateway.core.logging.LoggableProxyConnection.write(LoggableProxyConnection.java:104)
    at io.gravitee.gateway.core.logging.LoggableProxyConnection.write(LoggableProxyConnection.java:39)
    at io.gravitee.gateway.core.invoker.EndpointInvoker.lambda$invoke$2(EndpointInvoker.java:79)
    at io.gravitee.gateway.core.processor.chain.AbstractStreamableProcessorChain.lambda$handle$5(AbstractStreamableProcessorChain.java:70)
    at io.gravitee.gateway.core.processor.EmptyStreamableProcessor.write(EmptyStreamableProcessor.java:47)
    at io.gravitee.gateway.core.processor.chain.AbstractStreamableProcessorChain.lambda$handle$5(AbstractStreamableProcessorChain.java:70)
    at io.gravitee.gateway.policy.impl.StreamablePolicyChain.write(StreamablePolicyChain.java:120)
    at io.gravitee.gateway.policy.impl.StreamablePolicyChain.write(StreamablePolicyChain.java:35)
    at io.gravitee.gateway.core.processor.chain.AbstractStreamableProcessorChain.write(AbstractStreamableProcessorChain.java:99)
    at io.gravitee.gateway.core.processor.StreamableProcessorDecorator.write(StreamableProcessorDecorator.java:74)
    at io.gravitee.gateway.policy.impl.StreamablePolicyChain.write(StreamablePolicyChain.java:120)
    at io.gravitee.gateway.policy.impl.StreamablePolicyChain.write(StreamablePolicyChain.java:35)
    at io.gravitee.gateway.core.processor.StreamableProcessorDecorator.write(StreamableProcessorDecorator.java:74)
    at io.gravitee.gateway.core.processor.EmptyStreamableProcessor.write(EmptyStreamableProcessor.java:47)
    at io.gravitee.gateway.core.processor.chain.AbstractStreamableProcessorChain.write(AbstractStreamableProcessorChain.java:99)
    at io.gravitee.gateway.core.logging.LoggableClientRequest.lambda$bodyHandler$0(LoggableClientRequest.java:68)
    at io.gravitee.gateway.http.vertx.VertxHttpServerRequest.lambda$bodyHandler$0(VertxHttpServerRequest.java:187)
    at io.vertx.core.impl.AbstractContext.dispatch(AbstractContext.java:100)
    at io.vertx.core.http.impl.HttpEventHandler.handleChunk(HttpEventHandler.java:51)
    at io.vertx.core.http.impl.Http1xServerRequest.onData(Http1xServerRequest.java:531)
    at io.vertx.core.http.impl.Http1xServerRequest.lambda$pendingQueue$1(Http1xServerRequest.java:128)
    at io.vertx.core.streams.impl.InboundBuffer.handleEvent(InboundBuffer.java:240)
    at io.vertx.core.streams.impl.InboundBuffer.drain(InboundBuffer.java:227)
    at io.vertx.core.streams.impl.InboundBuffer.lambda$fetch$0(InboundBuffer.java:280)
    at io.vertx.core.impl.AbstractContext.dispatch(AbstractContext.java:100)
    at io.vertx.core.impl.AbstractContext.dispatch(AbstractContext.java:63)
    at io.vertx.core.impl.EventLoopContext.lambda$runOnContext$0(EventLoopContext.java:38)
    at io.netty.util.concurrent.AbstractEventExecutor.safeExecute(AbstractEventExecutor.java:164)
    at io.netty.util.concurrent.SingleThreadEventExecutor.runAllTasks(SingleThreadEventExecutor.java:469)
    at io.netty.channel.epoll.EpollEventLoop.run(EpollEventLoop.java:387)
    at io.netty.util.concurrent.SingleThreadEventExecutor$4.run(SingleThreadEventExecutor.java:986)
    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(Unknown Source)
j-ova commented 9 months ago

Hello,

We have the same issue and it is getting problematic.

Every now and then the gateways start giving 504 response to every request until we re-deploy them. They look healthy on kubernetes, but the logs are filled with "NullPointerException" and at the top of them all we find the stack trace given in this issue.

Is there something we can do?

Thanks. Regards, J

meveno commented 8 months ago

Stil having the issue with the latest patch version ...

2023-12-21 14:51:23.195 +0100 [vert.x-eventloop-thread-2] [] ERROR io.vertx.core.impl.ContextImpl - Unhandled exception
java.lang.NullPointerException: Cannot invoke "io.vertx.core.http.HttpClientRequest.headers()" because "this.httpClientRequest" is null
    at io.gravitee.connector.http.HttpConnection.lambda$writeUpstreamHeaders$6(HttpConnection.java:324)
    at java.base/java.lang.Iterable.forEach(Unknown Source)
    at io.gravitee.connector.http.HttpConnection.writeUpstreamHeaders(HttpConnection.java:323)
    at io.gravitee.connector.http.HttpConnection.writeHeaders(HttpConnection.java:300)
    at io.gravitee.connector.http.HttpConnection.write(HttpConnection.java:280)
    at io.gravitee.connector.http.HttpConnection.write(HttpConnection.java:50)
    at io.gravitee.gateway.core.endpoint.factory.impl.EndpointFactoryImpl$ConnectorProxyConnection.write(EndpointFactoryImpl.java:120)
    at io.gravitee.gateway.core.endpoint.factory.impl.EndpointFactoryImpl$ConnectorProxyConnection.write(EndpointFactoryImpl.java:74)
    at io.gravitee.gateway.core.logging.LoggableProxyConnection.write(LoggableProxyConnection.java:104)
    at io.gravitee.gateway.core.logging.LoggableProxyConnection.write(LoggableProxyConnection.java:39)
    at io.gravitee.gateway.core.invoker.EndpointInvoker.lambda$invoke$2(EndpointInvoker.java:79)
    at io.gravitee.gateway.core.processor.chain.AbstractStreamableProcessorChain.lambda$handle$5(AbstractStreamableProcessorChain.java:76)
    at io.gravitee.gateway.core.processor.EmptyStreamableProcessor.write(EmptyStreamableProcessor.java:47)
    at io.gravitee.gateway.core.processor.chain.AbstractStreamableProcessorChain.lambda$handle$5(AbstractStreamableProcessorChain.java:76)
    at io.gravitee.gateway.policy.impl.StreamablePolicyChain.write(StreamablePolicyChain.java:120)
    at io.gravitee.gateway.policy.impl.StreamablePolicyChain.write(StreamablePolicyChain.java:35)
    at io.gravitee.gateway.core.processor.chain.AbstractStreamableProcessorChain.write(AbstractStreamableProcessorChain.java:105)
    at io.gravitee.gateway.core.processor.StreamableProcessorDecorator.write(StreamableProcessorDecorator.java:74)
    at io.gravitee.gateway.policy.impl.StreamablePolicyChain.write(StreamablePolicyChain.java:120)
    at io.gravitee.gateway.policy.impl.StreamablePolicyChain.write(StreamablePolicyChain.java:35)
    at io.gravitee.gateway.core.processor.StreamableProcessorDecorator.write(StreamableProcessorDecorator.java:74)
    at io.gravitee.gateway.core.processor.EmptyStreamableProcessor.write(EmptyStreamableProcessor.java:47)
    at io.gravitee.gateway.core.processor.chain.AbstractStreamableProcessorChain.write(AbstractStreamableProcessorChain.java:105)
    at io.gravitee.gateway.core.logging.LoggableClientRequest.lambda$bodyHandler$0(LoggableClientRequest.java:68)
    at io.gravitee.gateway.core.logging.LoggableClientRequest.lambda$bodyHandler$0(LoggableClientRequest.java:68)
    at io.gravitee.gateway.http.vertx.VertxHttpServerRequest.lambda$bodyHandler$0(VertxHttpServerRequest.java:187)
    at io.vertx.core.impl.AbstractContext.dispatch(AbstractContext.java:100)
    at io.vertx.core.http.impl.HttpEventHandler.handleChunk(HttpEventHandler.java:51)
    at io.vertx.core.http.impl.Http1xServerRequest.onData(Http1xServerRequest.java:531)
    at io.vertx.core.http.impl.Http1xServerRequest.lambda$pendingQueue$1(Http1xServerRequest.java:128)
    at io.vertx.core.streams.impl.InboundBuffer.handleEvent(InboundBuffer.java:240)
    at io.vertx.core.streams.impl.InboundBuffer.drain(InboundBuffer.java:227)
    at io.vertx.core.streams.impl.InboundBuffer.lambda$fetch$0(InboundBuffer.java:280)
    at io.vertx.core.impl.AbstractContext.dispatch(AbstractContext.java:100)
    at io.vertx.core.impl.AbstractContext.dispatch(AbstractContext.java:63)
    at io.vertx.core.impl.EventLoopContext.lambda$runOnContext$0(EventLoopContext.java:38)
    at io.netty.util.concurrent.AbstractEventExecutor.safeExecute(AbstractEventExecutor.java:164)
    at io.netty.util.concurrent.SingleThreadEventExecutor.runAllTasks(SingleThreadEventExecutor.java:469)
    at io.netty.channel.epoll.EpollEventLoop.run(EpollEventLoop.java:384)
    at io.netty.util.concurrent.SingleThreadEventExecutor$4.run(SingleThreadEventExecutor.java:986)
    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(Unknown Source)
meveno commented 8 months ago

After further investigation, it seems to happen on one unique configured API. This API is between a offline application that is using PouchDB library (v8.0.1) to sync local changes to a remote CouchDB server (v3.3.1).

meveno commented 8 months ago

We tried to make a small change (healthcheck period) to induce a API redeploy in the gateways. After the update, the API is available again and a lot of error are printed in the logs, talking about Connection closed, as you can see in the logs :

2023-12-21 17:40:49.555 +0100 [gio.sync-2] [d08c28b2-4fc7-44b1-8c28-b24fc754b140] INFO  i.g.g.h.a.m.impl.ApiManagerImpl -   - JWT
2023-12-21 17:41:09.605 +0100 [gio.sync-2] [d08c28b2-4fc7-44b1-8c28-b24fc754b140] WARN  i.g.connector.api.AbstractConnector - Cancel requests[399] for endpoint[default] target[http://pgc-rec-svc-couchdb.ovalt-pgc.svc.cluster.local:5984]
2023-12-21 17:41:09.611 +0100 [gio.sync-2] [d08c28b2-4fc7-44b1-8c28-b24fc754b140] INFO  i.g.g.h.a.m.impl.ApiManagerImpl - API id[d08c28b2-4fc7-44b1-8c28-b24fc754b140] name[altere-couchdb] version[1.0.0] has been updated
2023-12-21 17:41:09.611 +0100 [vert.x-eventloop-thread-1] [] ERROR i.g.connector.http.HttpConnection - Unexpected error while handling backend response for request GET http://pgc-rec-svc-couchdb.ovalt-pgc.svc.cluster.local:5984/referentiels/_changes?style=all_docs&feed=longpoll&heartbeat=10000&since=1160-g1AAAAFxeJzLYWBgYMpgTmFwTc4vTc5ISXIoSE_WLUpN1oXydQ300ET08ssSc0p0gaJ6xWXJesk5pcUlqUV6OfnJiTk5IOMSGZLq____n5XBnMTAwFifCxRjN00xTTZLM6CWPVR2cR4LkGRoAFL_4Q5n5gQ73NzMKDXJ0JRa1mUBAEz4fK0&limit=100 - Connection was closed
2023-12-21 17:41:09.611 +0100 [vert.x-eventloop-thread-1] [] ERROR i.g.connector.http.HttpConnection - Unexpected error while handling backend response for request GET http://pgc-rec-svc-couchdb.ovalt-pgc.svc.cluster.local:5984/referentiels/_changes?style=all_docs&feed=longpoll&heartbeat=10000&since=1160-g1AAAAFxeJzLYWBgYMpgTmFwTc4vTc5ISXIoSE_WLUpN1oXydQ300ET08ssSc0p0gaJ6xWXJesk5pcUlqUV6OfnJiTk5IOMSGZLq____n5XBnMTAwFifCxRjN00xTTZLM6CWPVR2cR4LkGRoAFL_4Q5n5gQ73NzMKDXJ0JRa1mUBAEz4fK0&limit=100 - Connection was closed
2023-12-21 17:41:09.611 +0100 [vert.x-eventloop-thread-1] [] ERROR i.g.connector.http.HttpConnection - Unexpected error while handling backend response for request GET http://pgc-rec-svc-couchdb.ovalt-pgc.svc.cluster.local:5984/config/_changes?style=all_docs&feed=longpoll&heartbeat=10000&since=1-g1AAAAEVeJytjTsKgDAQRNcPeJosWtrZeJB1EwyyGjHRVm8eI1hZ28wwr3gjAJDbQkPPbmerh24dWW2G1btVjR-C7iAJKlH0ByPL7oPZUByTyKMjGM4Y40Tws3gpU8KVKj5-W1A2J1DppiWu27--phsQkl89&limit=100 - Connection was closed
2023-12-21 17:41:09.612 +0100 [vert.x-eventloop-thread-1] [] ERROR i.g.connector.http.HttpConnection - Unexpected error while handling backend response for request GET http://pgc-rec-svc-couchdb.ovalt-pgc.svc.cluster.local:5984/config/_changes?style=all_docs&feed=longpoll&heartbeat=10000&since=1-g1AAAAEVeJytjTsKgDAQRNcPeJosWtrZeJB1EwyyGjHRVm8eI1hZ28wwr3gjAJDbQkPPbmerh24dWW2G1btVjR-C7iAJKlH0ByPL7oPZUByTyKMjGM4Y40Tws3gpU8KVKj5-W1A2J1DppiWu27--phsQkl89&limit=100 - Connection was closed
2023-12-21 17:41:09.612 +0100 [vert.x-eventloop-thread-1] [] ERROR i.g.connector.http.HttpConnection - Unexpected error while handling backend response for request GET http://pgc-rec-svc-couchdb.ovalt-pgc.svc.cluster.local:5984/referentiels/_changes?style=all_docs&feed=longpoll&heartbeat=10000&since=1160-g1AAAAFxeJzLYWBgYMpgTmFwTc4vTc5ISXIoSE_WLUpN1oXydQ300ET08ssSc0p0gaJ6xWXJesk5pcUlqUV6OfnJiTk5IOMSGZLq____n5XBnMTAwFifCxRjN00xTTZLM6CWPVR2cR4LkGRoAFL_4Q5n5gQ73NzMKDXJ0JRa1mUBAEz4fK0&limit=100 - Connection was closed
meveno commented 8 months ago

Seems other people are having the same issue : https://community.gravitee.io/t/gravitee-gateway-timeout-this-httpclientrequest-is-null/1727

meveno commented 6 months ago

Any update on this ?

stale[bot] commented 3 months ago

This issue has been automatically marked as stale because it has not had recent activity. It will be closed if no further activity occurs. Thank you for your contributions.