openfaas / nats-queue-worker

Queue-worker for OpenFaaS with NATS Streaming
https://docs.openfaas.com/reference/async/
MIT License
128 stars 59 forks source link

Merge queue-worker reconnect and fix bug in gateway reconnection logic #54

Closed alexellis closed 5 years ago

alexellis commented 5 years ago

Description

Closes #52

Motivation and Context

How Has This Been Tested?

I deployed modified gateways and queue-workers then scaled NATS to zero, saw the reconnection messages, scaled it back then was able to send a message successfully after the recovery.

s/gateway-69596ff4d7-f595q[gateway]: 2019/02/12 17:29:30 Disconnected from nats://nats.openfaas.svc.cluster.local:4222
openfaas/gateway-69596ff4d7-f595q[gateway]: 2019/02/12 17:29:30 Reconnect
openfaas/gateway-69596ff4d7-f595q[gateway]: 2019/02/12 17:29:30 Connect: nats://nats.openfaas.svc.cluster.local:4222
openfaas/gateway-69596ff4d7-f595q[gateway]: 2019/02/12 17:29:30 Forwarded [GET] to /system/functions - [200] - 0.003920 seconds
openfaas/gateway-69596ff4d7-f595q[gateway]: 2019/02/12 17:29:30 Forwarded [GET] to /healthz - [200] - 0.000306 seconds
openfaas/gateway-69596ff4d7-f595q[gateway]: 2019/02/12 17:29:31 Forwarded [GET] to /system/functions - [200] - 0.010235 seconds
openfaas/gateway-69596ff4d7-f595q[gateway]: 2019/02/12 17:29:32 Forwarded [GET] to /system/functions - [200] - 0.004000 seconds
openfaas/gateway-69596ff4d7-f595q[gateway]: 2019/02/12 17:29:32 Forwarded [GET] to /healthz - [200] - 0.000276 seconds
openfaas/queue-worker-86d7588d56-6hr77[queue-worker]: Disconnected from nats://nats.openfaas.svc.cluster.local:4222
openfaas/queue-worker-86d7588d56-6hr77[queue-worker]: Connecting to: nats://nats.openfaas.svc.cluster.local:4222
openfaas/gateway-69596ff4d7-f595q[gateway]: 2019/02/12 17:29:32 Reconnecting (1/60) to nats://nats.openfaas.svc.cluster.local:4222 failed
openfaas/gateway-69596ff4d7-f595q[gateway]: 2019/02/12 17:29:33 Forwarded [GET] to /system/functions - [200] - 0.004987 seconds
openfaas/gateway-69596ff4d7-f595q[gateway]: 2019/02/12 17:29:34 Forwarded [GET] to /system/functions - [200] - 0.004020 seconds
openfaas/queue-worker-86d7588d56-6hr77[queue-worker]: Reconnecting (1/120) to nats://nats.openfaas.svc.cluster.local:4222 failed
openfaas/queue-worker-86d7588d56-6hr77[queue-worker]: Waiting 2s before next try
openfaas/gateway-69596ff4d7-f595q[gateway]: 2019/02/12 17:29:34 Connect: nats://nats.openfaas.svc.cluster.local:4222
openfaas/gateway-69596ff4d7-f595q[gateway]: 2019/02/12 17:29:35 Forwarded [GET] to /system/functions - [200] - 0.009519 seconds
openfaas/queue-worker-86d7588d56-6hr77[queue-worker]: Connecting to: nats://nats.openfaas.svc.cluster.local:4222
openfaas/gateway-69596ff4d7-f595q[gateway]: 2019/02/12 17:29:36 Reconnecting (2/60) to nats://nats.openfaas.svc.cluster.local:4222 failed
openfaas/gateway-69596ff4d7-f595q[gateway]: 2019/02/12 17:29:36 Forwarded [GET] to /system/functions - [200] - 0.003693 seconds
openfaas/gateway-69596ff4d7-f595q[gateway]: 2019/02/12 17:29:37 Forwarded [GET] to /system/functions - [200] - 0.003020 seconds
openfaas/gateway-69596ff4d7-f595q[gateway]: 2019/02/12 17:29:38 Forwarded [GET] to /system/functions - [200] - 0.003875 seconds
openfaas/queue-worker-86d7588d56-6hr77[queue-worker]: Reconnecting (2/120) to nats://nats.openfaas.svc.cluster.local:4222 failed
openfaas/queue-worker-86d7588d56-6hr77[queue-worker]: Waiting 4s before next try
openfaas/gateway-69596ff4d7-f595q[gateway]: 2019/02/12 17:29:39 Forwarded [GET] to /system/functions - [200] - 0.004449 seconds
openfaas/gateway-69596ff4d7-f595q[gateway]: 2019/02/12 17:29:40 Forwarded [GET] to /system/functions - [200] - 0.004419 seconds
openfaas/gateway-69596ff4d7-f595q[gateway]: 2019/02/12 17:29:40 Connect: nats://nats.openfaas.svc.cluster.local:4222
openfaas/gateway-69596ff4d7-f595q[gateway]: 2019/02/12 17:29:40 Forwarded [GET] to /healthz - [200] - 0.000310 seconds
openfaas/gateway-69596ff4d7-f595q[gateway]: 2019/02/12 17:29:41 Forwarded [GET] to /system/functions - [200] - 0.004071 seconds
openfaas/gateway-69596ff4d7-f595q[gateway]: 2019/02/12 17:29:42 Forwarded [GET] to /healthz - [200] - 0.000228 seconds
openfaas/queue-worker-86d7588d56-6hr77[queue-worker]: Connecting to: nats://nats.openfaas.svc.cluster.local:4222
openfaas/gateway-69596ff4d7-f595q[gateway]: 2019/02/12 17:29:42 Reconnecting (3/60) to nats://nats.openfaas.svc.cluster.local:4222 failed
openfaas/gateway-69596ff4d7-f595q[gateway]: 2019/02/12 17:29:42 Forwarded [GET] to /system/functions - [200] - 0.004295 seconds
openfaas/gateway-69596ff4d7-f595q[gateway]: 2019/02/12 17:29:43 Forwarded [GET] to /system/functions - [200] - 0.004441 seconds
openfaas/gateway-69596ff4d7-f595q[gateway]: 2019/02/12 17:29:44 Forwarded [GET] to /system/functions - [200] - 0.004405 seconds
openfaas/queue-worker-86d7588d56-6hr77[queue-worker]: Reconnecting (3/120) to nats://nats.openfaas.svc.cluster.local:4222 failed
openfaas/queue-worker-86d7588d56-6hr77[queue-worker]: Waiting 6s before next try
openfaas/gateway-69596ff4d7-f595q[gateway]: 2019/02/12 17:29:45 Forwarded [GET] to /system/functions - [200] - 0.005420 seconds
openfaas/gateway-69596ff4d7-f595q[gateway]: 2019/02/12 17:29:46 Forwarded [GET] to /system/functions - [200] - 0.004184 seconds
openfaas/gateway-69596ff4d7-f595q[gateway]: 2019/02/12 17:29:47 Forwarded [GET] to /system/functions - [200] - 0.004441 seconds
openfaas/gateway-69596ff4d7-f595q[gateway]: 2019/02/12 17:29:48 Connect: nats://nats.openfaas.svc.cluster.local:4222
openfaas/gateway-69596ff4d7-f595q[gateway]: 2019/02/12 17:29:48 Forwarded [GET] to /system/functions - [200] - 0.004233 seconds
openfaas/gateway-69596ff4d7-f595q[gateway]: 2019/02/12 17:29:49 Forwarded [GET] to /system/functions - [200] - 0.004060 seconds
openfaas/gateway-69596ff4d7-f595q[gateway]: 2019/02/12 17:29:50 Forwarded [GET] to /system/functions - [200] - 0.004519 seconds
openfaas/queue-worker-86d7588d56-6hr77[queue-worker]: Connecting to: nats://nats.openfaas.svc.cluster.local:4222
openfaas/gateway-69596ff4d7-f595q[gateway]: 2019/02/12 17:29:50 Reconnecting (4/60) to nats://nats.openfaas.svc.cluster.local:4222 failed
openfaas/gateway-69596ff4d7-f595q[gateway]: 2019/02/12 17:29:50 Forwarded [GET] to /healthz - [200] - 0.000596 seconds
openfaas/gateway-69596ff4d7-f595q[gateway]: 2019/02/12 17:29:51 Forwarded [GET] to /system/functions - [200] - 0.005306 seconds
openfaas/gateway-69596ff4d7-f595q[gateway]: 2019/02/12 17:29:52 Forwarded [GET] to /healthz - [200] - 0.000256 seconds
openfaas/gateway-69596ff4d7-f595q[gateway]: 2019/02/12 17:29:52 Forwarded [GET] to /system/functions - [200] - 0.003906 seconds
openfaas/queue-worker-86d7588d56-6hr77[queue-worker]: Reconnecting (4/120) to nats://nats.openfaas.svc.cluster.local:4222 failed
openfaas/queue-worker-86d7588d56-6hr77[queue-worker]: Waiting 8s before next try
openfaas/gateway-69596ff4d7-f595q[gateway]: 2019/02/12 17:29:53 Forwarded [GET] to /system/functions - [200] - 0.004238 seconds
openfaas/gateway-69596ff4d7-f595q[gateway]: 2019/02/12 17:29:54 Forwarded [GET] to /system/functions - [200] - 0.004700 seconds
openfaas/gateway-69596ff4d7-f595q[gateway]: 2019/02/12 17:29:55 Forwarded [GET] to /system/functions - [200] - 0.004442 seconds
openfaas/gateway-69596ff4d7-f595q[gateway]: 2019/02/12 17:29:56 Forwarded [GET] to /system/functions - [200] - 0.010658 seconds
openfaas/gateway-69596ff4d7-f595q[gateway]: 2019/02/12 17:29:57 Forwarded [GET] to /system/functions - [200] - 0.004240 seconds
openfaas/gateway-69596ff4d7-f595q[gateway]: 2019/02/12 17:29:58 Forwarded [GET] to /system/functions - [200] - 0.004012 seconds
openfaas/gateway-69596ff4d7-f595q[gateway]: 2019/02/12 17:29:58 Connect: nats://nats.openfaas.svc.cluster.local:4222
openfaas/gateway-69596ff4d7-f595q[gateway]: 2019/02/12 17:29:58 Reconnecting (5/60) to nats://nats.openfaas.svc.cluster.local:4222. OK
openfaas/gateway-69596ff4d7-f595q[gateway]: 2019/02/12 17:29:59 Forwarded [GET] to /system/functions - [200] - 0.004833 seconds
openfaas/gateway-69596ff4d7-f595q[gateway]: 2019/02/12 17:29:59 Forwarded [GET] to /system/functions - [200] - 0.004211 seconds
openfaas/queue-worker-86d7588d56-6hr77[queue-worker]: Connecting to: nats://nats.openfaas.svc.cluster.local:4222
openfaas/queue-worker-86d7588d56-6hr77[queue-worker]: Subscribing to: faas-request at nats://nats.openfaas.svc.cluster.local:4222
openfaas/queue-worker-86d7588d56-6hr77[queue-worker]: Wait for  15m0s
openfaas/queue-worker-86d7588d56-6hr77[queue-worker]: Listening on [faas-request], clientID=[faas-worker-queue-worker-86d7588d56-6hr77], qgroup=[faas] durable=[]
openfaas/queue-worker-86d7588d56-6hr77[queue-worker]: Reconnecting (5/120) to nats://nats.openfaas.svc.cluster.local:4222 succeeded
openfaas/gateway-69596ff4d7-f595q[gateway]: 2019/02/12 17:30:00 Forwarded [GET] to /system/functions - [200] - 0.004267 seconds
openfaas/gateway-69596ff4d7-f595q[gateway]: 2019/02/12 17:30:00 Forwarded [GET] to /healthz - [200] - 0.000257 seconds
openfaas/gateway-69596ff4d7-f595q[gateway]: 2019/02/12 17:30:01 Forwarded [GET] to /system/functions - [200] - 0.004281 seconds
openfaas/gateway-69596ff4d7-f595q[gateway]: 2019/02/12 17:30:02 Forwarded [GET] to /system/functions - [200] - 0.004128 seconds
openfaas/gateway-69596ff4d7-f595q[gateway]: 2019/02/12 17:30:02 Forwarded [GET] to /healthz - [200] - 0.000262 seconds
openfaas/gateway-69596ff4d7-f595q[gateway]: 2019/02/12 17:30:03 Forwarded [GET] to /system/functions - [200] - 0.005115 seconds
openfaas/gateway-69596ff4d7-f595q[gateway]: 2019/02/12 17:30:04 Forwarded [GET] to /system/functions - [200] - 0.004039 seconds
openfaas/gateway-69596ff4d7-f595q[gateway]: 2019/02/12 17:30:05 Forwarded [GET] to /system/functions - [200] - 0.004262 seconds
openfaas/gateway-69596ff4d7-f595q[gateway]: 2019/02/12 17:30:06 Forwarded [GET] to /system/functions - [200] - 0.010470 seconds
openfaas/gateway-69596ff4d7-f595q[gateway]: 2019/02/12 17:30:07 Forwarded [GET] to /system/functions - [200] - 0.004210 seconds
openfaas/gateway-69596ff4d7-f595q[gateway]: 2019/02/12 17:30:08 Forwarded [GET] to /system/functions - [200] - 0.004135 seconds
openfaas/gateway-69596ff4d7-f595q[gateway]: 2019/02/12 17:30:09 Forwarded [GET] to /system/functions - [200] - 0.003731 seconds
openfaas/gateway-69596ff4d7-f595q[gateway]: NatsQueue - submitting request: go-echo.
openfaas/gateway-69596ff4d7-f595q[gateway]: 2019/02/12 17:30:10 Forwarded [POST] to /async-function/go-echo - [202] - 0.001563 seconds
openfaas/queue-worker-86d7588d56-6hr77[queue-worker]: [#16] Received on [faas-request]: 'sequence:1 subject:"faas-request" data:"{\"Header\":{\"Accept\":[\"*/*\"],\"Content-Length\":[\"4\"],\"Content-Type\":[\"application/x-www-form-urlencoded\"],\"User-Agent\":[\"curl/7.54.0\"],\"X-Call-Id\":[\"94232a0d-668b-4636-a3de-9ae99a62dd84\"],\"X-Start-Time\":[\"1549992610028210333\"]},\"Host\":\"192.168.0.26:31112\",\"Body\":\"dGVzdA==\",\"Method\":\"POST\",\"Path\":\"\",\"QueryString\":\"\",\"Function\":\"go-echo\",\"CallbackUrl\":null}" timestamp:1549992610036646716 '
openfaas/queue-worker-86d7588d56-6hr77[queue-worker]: Request for go-echo.
openfaas/queue-worker-86d7588d56-6hr77[queue-worker]: Wrote 4 Bytes
openfaas/queue-worker-86d7588d56-6hr77[queue-worker]: 200 OK
openfaas/gateway-69596ff4d7-f595q[gateway]: 2019/02/12 17:30:10 Forwarded [POST] to /system/async-report - [202] - 0.000095 seconds
openfaas/gateway-69596ff4d7-f595q[gateway]: 2019/02/12 17:30:10 Forwarded [POST] to /system/async-report - [202] - 0.000161 seconds
openfaas/queue-worker-86d7588d56-6hr77[queue-worker]: Posting report - 202
openfaas/gateway-69596ff4d7-f595q[gateway]: 2019/02/12 17:30:10 Forwarded [GET] to /system/functions - [200] - 0.004862 seconds
openfaas/gateway-69596ff4d7-f595q[gateway]: 2019/02/12 17:30:10 Forwarded [GET] to /healthz - [200] - 0.000248 seconds
openfaas/gateway-69596ff4d7-f595q[gateway]: 2019/02/12 17:30:11 Forwarded [GET] to /system/functions - [200] - 0.004438 seconds
openfaas/gateway-69596ff4d7-f595q[gateway]: NatsQueue - submitting request: go-echo.
openfaas/queue-worker-86d7588d56-6hr77[queue-worker]: [#17] Received on [faas-request]: 'sequence:2 subject:"faas-request" data:"{\"Header\":{\"Accept\":[\"*/*\"],\"Content-Length\":[\"4\"],\"Content-Type\":[\"application/x-www-form-urlencoded\"],\"User-Agent\":[\"curl/7.54.0\"],\"X-Call-Id\":[\"3c1e6521-ed63-43b2-bca3-0332feef31c3\"],\"X-Start-Time\":[\"1549992612368343269\"]},\"Host\":\"192.168.0.26:31112\",\"Body\":\"dGVzdA==\",\"Method\":\"POST\",\"Path\":\"\",\"QueryString\":\"\",\"Function\":\"go-echo\",\"CallbackUrl\":null}" timestamp:1549992612376733334 '
openfaas/queue-worker-86d7588d56-6hr77[queue-worker]: Request for go-echo.
openfaas/gateway-69596ff4d7-f595q[gateway]: 2019/02/12 17:30:12 Forwarded [POST] to /async-function/go-echo - [202] - 0.001309 seconds
openfaas/queue-worker-86d7588d56-6hr77[queue-worker]: Wrote 4 Bytes
openfaas/queue-worker-86d7588d56-6hr77[queue-worker]: 200 OK
openfaas/queue-worker-86d7588d56-6hr77[queue-worker]: Posting report - 202

Types of changes

Checklist: