Rejected requests during kubernetes deployments

[theZappr]

Hi All :)

We have about 10 moleculer projects bringing together about 20 services all talking through nats-operator in K8s. In production we also have multiple replicas for each project. So it is a lot of moleculer nodes.

The K8s deployments have RollingUpdates with maxSurge and maxUnavailable and readiness delays to make the deployments as uptimey as possible and moleculer has tracking enabled for graceful shutdowns.

However, despite this some requests are still being rejected during k8s deployments. I think it is because the "old" terminated node is still being sent requests when it shouldn't be. In our dev environment I am about to start digging into the metrics & logs on the NATS cluster to understand what is happening.

In the meantime though, has anyone found this and if so what workarounds have you tried? I am assuming some config tweak is needed in either moleculer or NATS (or both) to improve it. Is it a good idea to trap rejected requests on the gateway and just retry them?

Many thanks for any info.

To the moleculerjs team: "Awesome work!"

[intech]

@theZappr Maybe you could collect more information about this situation by using trace mode, what exactly is happening at this moment from the side of the transport

   logLevel: {
     "TRANS*": "trace",
     "**": "info"
   }

[theZappr]

Thanks for the quick reply :)

I did what you said on the moleculer gateway node in our dev K8s server. The log showing the problem is reproduced below. I have sanitised it for brevity. Possibly the lifecycle "unpublish services" step is either not happening OR needs a delay to allow the other services time to register that it's services are no longer available?

Do I need different debug settings to see the unpublishing of the services?

Both pods are running moleculer 0.14.18, if that helps.

# k8s adds the new node
[2022-12-22T10:26:27.776Z] INFO  gateway-node/REGISTRY: Node 'new-node' connected.
[2022-12-22T10:26:30.005Z] INFO  gateway-node/GATEWAY: => GET /...
[2022-12-22T10:26:30.007Z] INFO  gateway-node/GATEWAY:    Call 'test.service' action

# new request goes to the old node not yet terminated by k8s 
[2022-12-22T10:26:30.007Z] DEBUG gateway-node/TRANSIT: => Send 'test.service' request to 'terminating-node' node.
[2022-12-22T10:26:30.547Z] DEBUG gateway-node/TRANSIT: <= Response 'test.service' is received from 'terminating-node'.
[2022-12-22T10:26:30.548Z] INFO  gateway-node/GATEWAY: <= 200 GET /... [... ms]

# another request comes in, RRd to new node
[2022-12-22T10:26:34.782Z] INFO  gateway-node/GATEWAY: => GET /...
[2022-12-22T10:26:34.784Z] INFO  gateway-node/GATEWAY:    Call 'test.service' action
[2022-12-22T10:26:34.784Z] DEBUG gateway-node/TRANSIT: => Send 'test.service' request to 'new-node' node.
[2022-12-22T10:26:35.750Z] DEBUG gateway-node/TRANSIT: <= Response 'test.service' is received from 'new-node'.
[2022-12-22T10:26:35.751Z] INFO  gateway-node/GATEWAY: <= 200 GET /... [... ms]
[2022-12-22T10:26:36.055Z] DEBUG gateway-node/TRANSPORTER: NATS client pingTimer: 1

# another request, this time to the old node again
[2022-12-22T10:26:53.067Z] INFO  gateway-node/GATEWAY: => GET /...
[2022-12-22T10:26:53.070Z] INFO  gateway-node/GATEWAY:    Call 'test.service' action
[2022-12-22T10:26:53.070Z] DEBUG gateway-node/TRANSIT: => Send 'test.service' request to 'terminating-node' node.

# but it is not there
[2022-12-22T10:27:06.654Z] WARN  gateway-node/DISCOVERY: Heartbeat is not received from 'terminating-node' node.
[2022-12-22T10:27:06.659Z] WARN  gateway-node/REGISTRY: Node 'terminating-node' disconnected unexpectedly.
[2022-12-22T10:27:06.659Z] DEBUG gateway-node/TRANSIT: Remove pending requests of 'terminating-node' node.

# request rejected <<< the problem
[2022-12-22T10:27:06.661Z] ERROR gateway-node/GATEWAY:    Request error! RequestRejectedError : Request is rejected when call 'test.service' action on 'terminating-node' node. 
 RequestRejectedError: Request is rejected when call 'test.service' action on 'terminating-node' node.
    at /.../node_modules/moleculer/src/transit.js:1023:6
...
Data: { action: 'test.service', nodeID: 'terminating-node' }
[2022-12-22T10:27:06.664Z] ERROR gateway-node/GATEWAY: { responsedata... }
...

# much later the old node is removed
[2022-12-22T10:36:36.651Z] WARN  gateway-node/DISCOVERY: Removing offline 'terminating-node' node from registry because it hasn't submitted heartbeat signal for 10 minutes.

[intech]

In version 0.14.22, a bug was fixed with sending data about services when the broker was stopped. Perhaps this is your case.
But for some reason, I see a problem in the logs that the request is still sent to this node in the absence of a heartbeat, although it should be in the registry with the offline flag.

[theZappr]

Thanks again @intech.

I have updated the two projects I am testing with in dev to moleculer 0.14.27. The issue remains. Requests are sent to terminated nodes. With 'TRANS*',DISCOVERY and REGISTRY also set to trace on the gateway node I am not seeing services change when then "terminating node" shuts down. The first I see of it on the gateway node is always Heartbeat is not received from '...-cbc9d8f57-8t5sh-19' node if I am lucky.

I would expect to see something about the terminating node's published services set being changed to "none" or whatever when it starts is shutdown, before the heartbeat is considered "late" (if that is what is happening).

I will keep ramping up the debugging. Is it possible to get a live dump of the registry?

Tomorrow I will also check our gateway is up to date. Don't want to make that mistake again :P

Thanks again :)

[intech]

@theZappr you can take a live dump of the registry with your env by moleculer-cli call "$node.list" | jq (docs) or other internal actions

[theZappr]

OK found it. On my laptop SIGTERM triggers the broker shutdown as normal but in K8s SIGTERM is crashing the whole process

npm ERR! path /app
npm ERR! command failed
npm ERR! signal SIGTERM

so the graceful shutdown never happens :( this is why the registries are not informed.

I will do more digging.

[theZappr]

Yeah I found it. It' s a Dockerfile issue. It shouldn't be using npm start to run the app.

Not a moleculer issue at all.

Thank you for your input @intech :)

[icebob]

Yeah, it's a common NPM issue, the signals are not transferred to the node process. The recommended CMD command in Dockerfile:

# Start server
CMD ["node", "./node_modules/moleculer/bin/moleculer-runner.js"]