401 when redis is configured

[mattbartel-tyler]

We are attempting to set up the relay proxy in our k8s cluster and are getting 401s but only when a REDIS_ADDRESS is provided. As soon as we remove that configuration it starts working. The proxy is being called from a .net 6 API using your sdk.

Here's some logs from ff-proxy:

{"level":"info","ts":"2022-11-18T20:38:32Z","caller":"ff-proxy/main.go:308","msg":"service config","pprof":false,"debug":false,"bypass-auth":false,"offline":false,"port":8000,"admin-service":"https://app.harness.io/gateway/cf","account-identifier":"***REDACTED***","org-identifier":"default","sdk-base-url":"https://config.ff.harness.io/api/1.0","sdk-events-url":"https://events.ff.harness.io/api/1.0","redis-addr":"***REDACTED***","redis-db":0,"api-keys":"[***REDACTED***]","target-poll-duration":"60s","heartbeat-interval":"60s","flag-stream-enabled":true,"flag-poll-interval":"1m","config-dir":"/config"}
{"level":"info","ts":"2022-11-18T20:38:32Z","caller":"ff-proxy/main.go:325","msg":"connecting to redis","address":"***REDACTED***"}
{"level":"info","ts":"2022-11-18T20:38:32Z","caller":"ff-proxy/main.go:359","msg":"retrieving config from ff-server..."}
[INFO] 2022-11-18 20:38:32.370 starting...
[INFO] 2022-11-18 20:38:32.371 using config: /etc/pushpin/pushpin.conf
[INFO] 2022-11-18 20:38:32.371 starting condure
[INFO] 2022-11-18 20:38:32.371 starting zurl
[INFO] 2022-11-18 20:38:32.372 starting proxy
[INFO] 2022-11-18 20:38:32.372 starting handler
[INFO] 2022-11-18 20:38:32.398 started
{"level":"info","ts":"2022-11-18T20:38:35Z","caller":"ff-proxy/main.go:373","msg":"successfully retrieved config from FeatureFlags"}
{"level":"info","ts":1668803915.8538802,"caller":"cache/lru.go:25","msg":"Cache successfully initialized with size: 10000"}
2022/11/18 20:38:35 mkdir /nonexistent/harness: no such file or directory
{"level":"info","ts":1668803915.854061,"caller":"log/log.go:40","msg":"Cache successfully initialized with size: 10000"}
{"level":"info","ts":"2022-11-18T20:38:35Z","caller":"analyticsservice/analytics.go:103","msg":"Analytics cache successfully initialized","component":"SDK","apiKey":"***REDACTED***","environmentID":"f3f875b8-5645-4feb-b99b-1895ef2f3942","environment_identifier":"TCPCI","project_identifier":"Cloud_Platform"}
{"level":"info","ts":"2022-11-18T20:38:35Z","caller":"ff-proxy/main.go:464","msg":"starting stream worker..."}
{"level":"info","ts":"2022-11-18T20:38:35Z","caller":"app/stream_worker.go:54","msg":"starting stream worker","component":"StreamWorker","topic":"f3f875b8-5645-4feb-b99b-1895ef2f3942"}
{"level":"info","ts":"2022-11-18T20:38:35Z","caller":"transport/http_server.go:51","msg":"starting http server","component":"HTTPServer","addr":":8000"}
{"level":"info","ts":"2022-11-18T20:38:35Z","caller":"ff-proxy/main.go:533","msg":"polling for new targets every 60 seconds"}
{"level":"info","ts":"2022-11-18T20:38:35Z","caller":"ff-proxy/main.go:573","msg":"polling heartbeat every 60 seconds"}
{"level":"info","ts":"2022-11-18T20:38:35Z","caller":"ff-proxy/main.go:544","msg":"sending metrics every 60 seconds"}
{"level":"info","ts":"2022-11-18T20:38:36Z","caller":"client/client.go:310","msg":"Authentication complete","component":"SDK","apiKey":"***REDACTED***","environmentID":"f3f875b8-5645-4feb-b99b-1895ef2f3942","environment_identifier":"TCPCI","project_identifier":"Cloud_Platform"}
{"level":"info","ts":"2022-11-18T20:38:36Z","caller":"client/client.go:409","msg":"Posting analytics data enabled","component":"SDK","apiKey":"***REDACTED***","environmentID":"f3f875b8-5645-4feb-b99b-1895ef2f3942","environment_identifier":"TCPCI","project_identifier":"Cloud_Platform"}
{"level":"info","ts":"2022-11-18T20:38:36Z","caller":"client/client.go:382","msg":"Retrieving segments started","component":"SDK","apiKey":"***REDACTED***","environmentID":"f3f875b8-5645-4feb-b99b-1895ef2f3942","environment_identifier":"TCPCI","project_identifier":"Cloud_Platform"}
{"level":"info","ts":"2022-11-18T20:38:36Z","caller":"client/client.go:358","msg":"Retrieving flags started","component":"SDK","apiKey":"***REDACTED***","environmentID":"f3f875b8-5645-4feb-b99b-1895ef2f3942","environment_identifier":"TCPCI","project_identifier":"Cloud_Platform"}
{"level":"warn","ts":"2022-11-18T20:38:36Z","caller":"cache/wrapper.go:134","msg":"failed to set key to wrapper cache","component":"SDK","apiKey":"***REDACTED***","environmentID":"f3f875b8-5645-4feb-b99b-1895ef2f3942","environment_identifier":"TCPCI","project_identifier":"Cloud_Platform","component":"CacheWrapper","method":"Set","key":"target-segment/OpsCenterFeaturesDev","value":{***REDACTED***},"method":"deleteByType","keyType":"target-segment","method":"deleteByType","keyType":"flag","err":"MOVED 13879 172.10.145.86:6379"}
{"level":"warn","ts":"2022-11-18T20:38:36Z","caller":"cache/wrapper.go:134","msg":"failed to set key to wrapper cache","component":"SDK","apiKey":"***REDACTED***","environmentID":"f3f875b8-5645-4feb-b99b-1895ef2f3942","environment_identifier":"TCPCI","project_identifier":"Cloud_Platform","component":"CacheWrapper","method":"Set","key":"target-segment/OpsCenterFeaturesDev","value":{***REDACTED***},"method":"deleteByType","keyType":"target-segment","method":"deleteByType","keyType":"flag","method":"Set","key":"target-segment/OpsCenterFeaturesClusterDRTest","value":{***REDACTED***},"err":"MOVED 13879 172.10.145.86:6379"}
{"level":"warn","ts":"2022-11-18T20:38:36Z","caller":"cache/wrapper.go:134","msg":"failed to set key to wrapper cache","component":"SDK","apiKey":"***REDACTED***","environmentID":"f3f875b8-5645-4feb-b99b-1895ef2f3942","environment_identifier":"TCPCI","project_identifier":"Cloud_Platform","component":"CacheWrapper","method":"Set","key":"target-segment/OpsCenterFeaturesDev","value":{***REDACTED***},"method":"deleteByType","keyType":"target-segment","method":"deleteByType","keyType":"flag","method":"Set","key":"target-segment/OpsCenterFeaturesClusterDRTest","value":{***REDACTED***},"method":"Set","key":"target-segment/OpsCenterFeatures","value":{***REDACTED***},"err":"MOVED 13879 172.10.145.86:6379"}
{"level":"info","ts":"2022-11-18T20:38:36Z","caller":"client/client.go:396","msg":"Retrieving segments finished","component":"SDK","apiKey":"***REDACTED***","environmentID":"f3f875b8-5645-4feb-b99b-1895ef2f3942","environment_identifier":"TCPCI","project_identifier":"Cloud_Platform"}
{"level":"warn","ts":"2022-11-18T20:38:36Z","caller":"cache/wrapper.go:134","msg":"failed to set key to wrapper cache","component":"SDK","apiKey":"***REDACTED***","environmentID":"f3f875b8-5645-4feb-b99b-1895ef2f3942","environment_identifier":"TCPCI","project_identifier":"Cloud_Platform","component":"CacheWrapper","method":"Set","key":"target-segment/OpsCenterFeaturesDev","value":{***REDACTED***},"method":"deleteByType","keyType":"target-segment","method":"deleteByType","keyType":"flag","method":"Set","key":"target-segment/OpsCenterFeaturesClusterDRTest","value":{***REDACTED***},"method":"Set","key":"target-segment/OpsCenterFeatures","value":{***REDACTED***},"method":"Set","key":"flag/opscenter_deleteorganization","value":{***REDACTED***},"err":"MOVED 14576 172.10.145.86:6379"}
{"level":"warn","ts":"2022-11-18T20:38:36Z","caller":"cache/wrapper.go:134","msg":"failed to set key to wrapper cache","component":"SDK","apiKey":"***REDACTED***","environmentID":"f3f875b8-5645-4feb-b99b-1895ef2f3942","environment_identifier":"TCPCI","project_identifier":"Cloud_Platform","component":"CacheWrapper","method":"Set","key":"target-segment/OpsCenterFeaturesDev","value":{***REDACTED***},"method":"deleteByType","keyType":"target-segment","method":"deleteByType","keyType":"flag","method":"Set","key":"target-segment/OpsCenterFeaturesClusterDRTest","value":{***REDACTED***},"method":"Set","key":"target-segment/OpsCenterFeatures","value":{***REDACTED***},"method":"Set","key":"flag/opscenter_deleteorganization","value":{***REDACTED***},"method":"Set","key":"flag/opscenter_deleteworkspace","value":{***REDACTED***},"err":"MOVED 14576 172.10.145.86:6379"}
{"level":"warn","ts":"2022-11-18T20:38:36Z","caller":"cache/wrapper.go:134","msg":"failed to set key to wrapper cache","component":"SDK","apiKey":"***REDACTED***","environmentID":"f3f875b8-5645-4feb-b99b-1895ef2f3942","environment_identifier":"TCPCI","project_identifier":"Cloud_Platform","component":"CacheWrapper","method":"Set","key":"target-segment/OpsCenterFeaturesDev","value":{***REDACTED***},"method":"deleteByType","keyType":"target-segment","method":"deleteByType","keyType":"flag","method":"Set","key":"target-segment/OpsCenterFeaturesClusterDRTest","value":{***REDACTED***},"method":"Set","key":"target-segment/OpsCenterFeatures","value":{***REDACTED***},"method":"Set","key":"flag/opscenter_deleteorganization","value":{***REDACTED***},"method":"Set","key":"flag/opscenter_deleteworkspace","value":{***REDACTED***},"method":"Set","key":"flag/opscenter_managetyleropsusers","value":{***REDACTED***},"err":"MOVED 14576 172.10.145.86:6379"}
{"level":"info","ts":"2022-11-18T20:38:36Z","caller":"client/client.go:372","msg":"Retrieving flags finished","component":"SDK","apiKey":"***REDACTED***","environmentID":"f3f875b8-5645-4feb-b99b-1895ef2f3942","environment_identifier":"TCPCI","project_identifier":"Cloud_Platform"}
{"level":"info","ts":"2022-11-18T20:38:36Z","caller":"client/client.go:181","msg":"Data poll finished successfully","component":"SDK","apiKey":"***REDACTED***","environmentID":"f3f875b8-5645-4feb-b99b-1895ef2f3942","environment_identifier":"TCPCI","project_identifier":"Cloud_Platform"}
{"level":"info","ts":"2022-11-18T20:38:36Z","caller":"client/client.go:327","msg":"Attempting to start stream","component":"SDK","apiKey":"***REDACTED***","environmentID":"f3f875b8-5645-4feb-b99b-1895ef2f3942","environment_identifier":"TCPCI","project_identifier":"Cloud_Platform"}
{"level":"info","ts":"2022-11-18T20:38:36Z","caller":"client/client.go:206","msg":"Registering SSE consumer","component":"SDK","apiKey":"***REDACTED***","environmentID":"f3f875b8-5645-4feb-b99b-1895ef2f3942","environment_identifier":"TCPCI","project_identifier":"Cloud_Platform"}
{"level":"info","ts":"2022-11-18T20:38:36Z","caller":"stream/sse.go:69","msg":"Start subscribing to Stream","component":"SDK","apiKey":"***REDACTED***","environmentID":"f3f875b8-5645-4feb-b99b-1895ef2f3942","environment_identifier":"TCPCI","project_identifier":"Cloud_Platform"}
{"level":"error","ts":"2022-11-18T20:39:00Z","caller":"log/log.go:114","msg":"failed to generate auth token","component":"ProxyService","method":"Authenticate","err":"Key \"***REDACTED***\" not found","reqID":"52cfe169-7e88-4891-9ecc-70138429b4b6"}
{"level":"info","ts":"2022-11-18T20:39:00Z","method":"POST","path":"/client/auth","status":"401","took":"1.270575ms","component":"LoggingMiddleware","reqID":"52cfe169-7e88-4891-9ecc-70138429b4b6"}
{"level":"error","ts":"2022-11-18T20:39:01Z","caller":"log/log.go:114","msg":"failed to generate auth token","component":"ProxyService","method":"Authenticate","err":"Key \"***REDACTED***\" not found","reqID":"ee2c1866-e550-49d1-a561-85b4f7fbb1eb"}
{"level":"info","ts":"2022-11-18T20:39:01Z","method":"POST","path":"/client/auth","status":"401","took":"1.248257ms","component":"LoggingMiddleware","reqID":"ee2c1866-e550-49d1-a561-85b4f7fbb1eb"}

[conormurray95]

Hey @mattbartel-tyler thanks for raising the issue and providing logs.
It appears from these error logs saving data to cache "err":"MOVED 14576 172.10.145.86:6379" that you're running a clustered redis instance. This isn't currently supported by the Relay Proxy, only standalone redis instances are.

Coming out of this issue I'll take a few actions:

1. Add a blocking redis healthcheck on startup, so if we have any connection issues it'll exit earlier and make this obvious rather than manifesting as errors writing to the cache later
2. Improve the docs to clarify that clustered redis instances aren't supported currently.

[conormurray95]

Extra implementation detail
Currently on startup we use go the go-redis library to connect to a redis client here - https://github.com/harness/ff-proxy/blob/main/cmd/ff-proxy/main.go#L320 using redis.NewClient().

Connecting to a cluster has a different api and connects using redis.NewClusterClient with these configuration options available to instantiate it with the defaults show below.

From what I can see the essential fields there might be username, password and addrs.

While it's not just a quick change we're always looking to expand our coverage of what we support so I'd be interested to hear your thoughts on which config options would be needed to support your usage of clustered redis.

[mattbartel-tyler]

Yep good catch, we've got a cluster running with AWS ElastiCache.

Those should be the only parameters we need for our use case. I'd expect the defaults for everything else to work fine.