Runtime error when calling get_data from Python middleware

Product Bug Reports
, , ,
1

Hello! I’m running Tyk with Redis in minikube cluster. I’m trying to load Redis keys from a Python middleware and getting a runtime error, here’s a snippet from Tyk logs:

time="Jul 05 16:34:26" level=debug msg="CoProcess Request, HookType: Pre" api_id=graphql api_name="GraphQL API" mw=CoProcessMiddleware org_id= origin=127.0.0.1 path="/api/"
time="Jul 05 16:34:26" level=info msg="PreHook is called" prefix=python
2022/07/05 16:34:26 http: panic serving 127.0.0.1:57040: runtime error: invalid memory address or nil pointer dereference
goroutine 259 [running]:
net/http.(*conn).serve.func1(0xc0008c92c0)
	/usr/local/go/src/net/http/server.go:1801 +0x147
panic(0x2276a80, 0x3480ac0)
	/usr/local/go/src/runtime/panic.go:975 +0x47a
github.com/TykTechnologies/tyk/storage.(*RedisController).Connected(...)
	/go/src/github.com/TykTechnologies/tyk/storage/redis_controller.go:63
github.com/TykTechnologies/tyk/storage.(*RedisCluster).up(0xc001123580, 0xc000478724, 0xc001123538)
	/go/src/github.com/TykTechnologies/tyk/storage/redis_cluster.go:159 +0x2a
github.com/TykTechnologies/tyk/storage.(*RedisCluster).GetKey(0xc001123580, 0xc000478724, 0x5, 0xc000640a02, 0xc00118a000, 0x994, 0x994)
	/go/src/github.com/TykTechnologies/tyk/storage/redis_cluster.go:167 +0x2f
github.com/TykTechnologies/tyk/gateway.TykGetData(0x7f315408ecb0, 0x0)

Error occurs when get_data APi call is invoked in Python code.
Tyk is able to connect to Redis, at least I see a tyk-liveness-probe key when manually connecting to Redis.

The full Tyk log from the beginning (I just removed sensitive info):

e[90m[Jul 05 16:34:02]e[0m e[34mDEBUGe[0m Using serializer protobuf for analytics 

time="Jul 05 16:34:02" level=debug msg="Using /opt/tyk-gateway/tyk.conf for configuration" prefix=main
time="Jul 05 16:34:02" level=info msg="Tyk API Gateway 4.1.0-rc15" prefix=main
time="Jul 05 16:34:02" level=error msg="Could not set version in versionStore" error="storage: Redis is either down or was not configured" prefix=main
time="Jul 05 16:34:02" level=debug msg="No Primary instance found, assuming control" prefix=host-check-mgr
time="Jul 05 16:34:02" level=error msg="cannot set key in pollerCacheKey" error="storage: Redis is either down or was not configured"
time="Jul 05 16:34:02" level=info msg="Starting Poller" prefix=host-check-mgr
time="Jul 05 16:34:02" level=debug msg="---> Initialising checker" prefix=host-check-mgr
time="Jul 05 16:34:02" level=debug msg="[HOST CHECKER] Config:TriggerLimit: 3"
time="Jul 05 16:34:02" level=debug msg="[HOST CHECKER] Config:Timeout: ~10"
time="Jul 05 16:34:02" level=debug msg="[HOST CHECKER] Config:WorkerPool: 16"
time="Jul 05 16:34:02" level=debug msg="[HOST CHECKER] Init complete"
time="Jul 05 16:34:02" level=debug msg="---> Starting checker" prefix=host-check-mgr
time="Jul 05 16:34:02" level=debug msg="Notifier will not work in hybrid mode" prefix=main
time="Jul 05 16:34:02" level=debug msg="[HOST CHECKER] Starting..."
time="Jul 05 16:34:02" level=debug msg="[HOST CHECKER] Check loop started..."
time="Jul 05 16:34:02" level=debug msg="[HOST CHECKER] Host reporter started..."
time="Jul 05 16:34:02" level=debug msg="---> Checker started." prefix=host-check-mgr
time="Jul 05 16:34:02" level=info msg="PIDFile location set to: /opt/tyk-gateway/middleware/tyk-gateway.pid" prefix=main
time="Jul 05 16:34:02" level=debug msg="Initialising default org store" prefix=main
time="Jul 05 16:34:02" level=error msg="Connection to Redis failed, reconnect in 10s" error="storage: Redis is either down or was not configured" prefix=pub-sub
time="Jul 05 16:34:02" level=info msg="Initialising Tyk REST API Endpoints" prefix=main
time="Jul 05 16:34:02" level=debug msg="Creating new Redis connection pool"
time="Jul 05 16:34:02" level=info msg="--> [REDIS] Creating single-node client"
time="Jul 05 16:34:02" level=debug msg="Loaded API Endpoints" prefix=main
time="Jul 05 16:34:02" level=info msg="--> Standard listener (http)" port=":8081" prefix=main
time="Jul 05 16:34:02" level=warning msg="Starting HTTP server on:[::]:8081" prefix=main
time="Jul 05 16:34:02" level=info msg="--> Standard listener (http)" port=":8080" prefix=main
time="Jul 05 16:34:02" level=warning msg="Starting HTTP server on:[::]:8080" prefix=main
time="Jul 05 16:34:02" level=info msg="Initialising distributed rate limiter" prefix=main
time="Jul 05 16:34:02" level=debug msg="DRL: Setting node ID: solo-08a4d556-0408-4e3e-8fcd-dd0da4d462de|api-gateway-7bcf48bf68-rlkxp"
time="Jul 05 16:34:02" level=info msg="Tyk Gateway started (4.1.0-rc15)" prefix=main
time="Jul 05 16:34:02" level=info msg="--> Listening on address: (open interface)" prefix=main
time="Jul 05 16:34:02" level=info msg="--> Listening on port: 8080" prefix=main
time="Jul 05 16:34:02" level=info msg="--> PID: 1" prefix=main
time="Jul 05 16:34:02" level=info msg="Loading policies" prefix=main
time="Jul 05 16:34:02" level=info msg="Loading policy from dir /opt/tyk-gateway/policies/auth-default.json"
time="Jul 05 16:34:02" level=info msg="Starting gateway rate limiter notifications..."
time="Jul 05 16:34:02" level=debug msg="Creating new Redis connection pool"
time="Jul 05 16:34:02" level=info msg="--> [REDIS] Creating single-node client"
time="Jul 05 16:34:02" level=info msg="Loading policy from dir /opt/tyk-gateway/policies/graphql-default.json"
time="Jul 05 16:34:02" level=info msg="Policies found (2 total):" prefix=main
time="Jul 05 16:34:02" level=debug msg=" - auth-default" prefix=main
time="Jul 05 16:34:02" level=debug msg=" - graphql-default" prefix=main
time="Jul 05 16:34:02" level=info msg="Loading API Specification from ... skipped"
time="Jul 05 16:34:02" level=debug msg="Creating new Redis connection pool"
time="Jul 05 16:34:02" level=info msg="--> [REDIS] Creating single-node client"
time="Jul 05 16:34:02" level=debug msg="Checking for transform paths..."
time="Jul 05 16:34:02" level=debug msg="Checking for transform paths..."
time="Jul 05 16:34:02" level=info msg="Loading API Specification from ... skipped"
time="Jul 05 16:34:02" level=debug msg="Checking for transform paths..."
time="Jul 05 16:34:02" level=debug msg="Checking for transform paths..."
time="Jul 05 16:34:02" level=info msg="Loading API Specification from /opt/tyk-gateway/apps/graphql.json"
time="Jul 05 16:34:02" level=debug msg="Checking for transform paths..."
time="Jul 05 16:34:02" level=debug msg="Checking for transform paths..."
time="Jul 05 16:34:02" level=info msg="Loading API Specification from ... skipped"
time="Jul 05 16:34:02" level=debug msg="Checking for transform paths..."
time="Jul 05 16:34:02" level=debug msg="Checking for transform paths..."
time="Jul 05 16:34:02" level=info msg="Loading API Specification from ... skipped"
time="Jul 05 16:34:02" level=debug msg="Checking for transform paths..."
time="Jul 05 16:34:02" level=debug msg="Checking for transform paths..."
time="Jul 05 16:34:02" level=info msg="Detected 5 APIs" prefix=main
time="Jul 05 16:34:02" level=info msg="Loading API configurations." prefix=main
time="Jul 05 16:34:02" level=info msg="Tracking hostname" api_name="... skipped" domain="(no host)" prefix=main
time="Jul 05 16:34:02" level=info msg="Tracking hostname" api_name="... skipped" domain="(no host)" prefix=main
time="Jul 05 16:34:02" level=info msg="Tracking hostname" api_name="... skipped" domain="(no host)" prefix=main
time="Jul 05 16:34:02" level=info msg="Tracking hostname" api_name="... skipped" domain="(no host)" prefix=main
time="Jul 05 16:34:02" level=info msg="Tracking hostname" api_name="GraphQL API" domain="(no host)" prefix=main
time="Jul 05 16:34:02" level=info msg="Initialising Tyk REST API Endpoints" prefix=main
time="Jul 05 16:34:02" level=debug msg="Loaded API Endpoints" prefix=main
time="Jul 05 16:34:02" level=info msg="API bind on custom port:0" prefix=main
time="Jul 05 16:34:02" level=debug msg="CORS ENABLED" prefix=main
time="Jul 05 16:34:02" level=debug msg="Initializing API" api_id=math-planning-service api_name="... skipped" org_id=
time="Jul 05 16:34:02" level=info msg="Checking security policy: Open" api_id=math-planning-service api_name="... skipped" org_id=
time="Jul 05 16:34:02" level=debug msg=Init api_id=math-planning-service api_name="... skipped" mw=VersionCheck org_id=
time="Jul 05 16:34:02" level=debug msg=Init api_id=math-planning-service api_name="... skipped" mw=RateCheckMW org_id=
time="Jul 05 16:34:02" level=debug msg=Init api_id=math-planning-service api_name="... skipped" mw=GraphQLMiddleware org_id=
time="Jul 05 16:34:02" level=info msg="API bind on custom port:0" prefix=main
time="Jul 05 16:34:02" level=debug msg="CORS ENABLED" prefix=main
time="Jul 05 16:34:02" level=info msg="API bind on custom port:0" prefix=main
time="Jul 05 16:34:02" level=debug msg="CORS ENABLED" prefix=main
time="Jul 05 16:34:02" level=info msg="API bind on custom port:0" prefix=main
time="Jul 05 16:34:02" level=debug msg="CORS ENABLED" prefix=main
time="Jul 05 16:34:02" level=info msg="API bind on custom port:0" prefix=main
time="Jul 05 16:34:02" level=debug msg="CORS ENABLED" prefix=main
time="Jul 05 16:34:02" level=info msg="Loading existing bundle: graphql.zip" prefix=main
time="Jul 05 16:34:02" level=info msg="----> Loading bundle: graphql.zip" prefix=main
time="Jul 05 16:34:02" level=info msg="----> Using bundle: graphql.zip" prefix=main
time="Jul 05 16:34:02" level=debug msg="Requested python version: """ prefix=dlpython
time="Jul 05 16:34:02" level=debug msg="Found python-config binary: 3.9 (/usr/bin/python3.9-config)" prefix=dlpython
time="Jul 05 16:34:02" level=debug msg="Using latest Python version" prefix=dlpython
time="Jul 05 16:34:02" level=debug msg="Selected Python configuration path: /usr/bin/python3.9-config" prefix=dlpython
time="Jul 05 16:34:02" level=debug msg="Selected Python library path: /usr/lib/python3.9/config-3.9-x86_64-linux-gnu/libpython3.9.so" prefix=dlpython
time="Jul 05 16:34:02" level=info msg="Python version '3.9' loaded" prefix=coprocess
time="Jul 05 16:34:02" level=info msg="Initializing dispatcher" prefix=python
time="Jul 05 16:34:02" level=info msg="Python dispatcher was initialized" prefix=coprocess
time="Jul 05 16:34:02" level=info msg="Loading module: 'bbbe963e4139eb4192928211174b81b8'" prefix=python
time="Jul 05 16:34:02" level=debug msg="Loading hook 'PreHook' (bbbe963e4139eb4192928211174b81b8)" prefix=python
time="Jul 05 16:34:02" level=debug msg="Initializing API" api_id=graphql api_name="GraphQL API" org_id=
time="Jul 05 16:34:02" level=debug msg="Loading custom PRE-PROCESSOR middleware: PreHook" prefix=main
time="Jul 05 16:34:02" level=debug msg=Init api_id=graphql api_name="GraphQL API" mw=VersionCheck org_id=
time="Jul 05 16:34:02" level=debug msg="Registering coprocess middleware, hook name: PreHookhook type: Pre, driver: python" api_id=graphql api_name="GraphQL API" org_id= prefix=coprocess
time="Jul 05 16:34:02" level=debug msg="Enabling CP middleware." prefix=coprocess
time="Jul 05 16:34:02" level=debug msg=Init api_id=graphql api_name="GraphQL API" mw=CoProcessMiddleware org_id=
time="Jul 05 16:34:02" level=debug msg=Init api_id=graphql api_name="GraphQL API" mw=RateCheckMW org_id=
time="Jul 05 16:34:02" level=debug msg=Init api_id=graphql api_name="GraphQL API" mw=JWTMiddleware org_id=
time="Jul 05 16:34:02" level=info msg="Checking security policy: JWT" api_id=graphql api_name="GraphQL API" org_id=
time="Jul 05 16:34:02" level=debug msg=Init api_id=graphql api_name="GraphQL API" mw=KeyExpired org_id=
time="Jul 05 16:34:02" level=debug msg=Init api_id=graphql api_name="GraphQL API" mw=AccessRightsCheck org_id=
time="Jul 05 16:34:02" level=debug msg=Init api_id=graphql api_name="GraphQL API" mw=GranularAccessMiddleware org_id=
time="Jul 05 16:34:02" level=debug msg=Init api_id=graphql api_name="GraphQL API" mw=RateLimitAndQuotaCheck org_id=
time="Jul 05 16:34:02" level=debug msg=Init api_id=graphql api_name="GraphQL API" mw=GraphQLMiddleware org_id=
time="Jul 05 16:34:02" level=debug msg=Init api_id=graphql api_name="GraphQL API" mw=GraphQLComplexityMiddleware org_id=
time="Jul 05 16:34:02" level=debug msg=Init api_id=graphql api_name="GraphQL API" mw=GraphQLGranularAccessMiddleware org_id=
time="Jul 05 16:34:02" level=debug msg=Init api_id=graphql api_name="GraphQL API" mw=VersionCheck org_id=
time="Jul 05 16:34:02" level=debug msg=Init api_id=graphql api_name="GraphQL API" mw=KeyExpired org_id=
time="Jul 05 16:34:02" level=debug msg=Init api_id=graphql api_name="GraphQL API" mw=AccessRightsCheck org_id=
time="Jul 05 16:34:02" level=debug msg="Rate limit endpoint is: /api/tyk/rate-limits" api_id=graphql api_name="GraphQL API" org_id=
time="Jul 05 16:34:02" level=debug msg="Setting Listen Path: /api/" api_id=graphql api_name="GraphQL API" org_id=
time="Jul 05 16:34:02" level=info msg="API Loaded" api_id=graphql api_name="GraphQL API" org_id= prefix=gateway server_name=-- user_id=-- user_ip=--
time="Jul 05 16:34:02" level=debug msg="Checker host list" prefix=main
time="Jul 05 16:34:02" level=info msg="Loading uptime tests..." prefix=host-check-mgr
time="Jul 05 16:34:02" level=debug msg="--- Setting tracking list up" prefix=host-check-mgr
time="Jul 05 16:34:02" level=debug msg="Reset initiated" prefix=host-check-mgr
time="Jul 05 16:34:02" level=debug msg="[HOST CHECKER] Checker reset queued!"
time="Jul 05 16:34:02" level=debug msg="Checker host Done" prefix=main
time="Jul 05 16:34:02" level=info msg="Initialised API Definitions" prefix=main
time="Jul 05 16:34:02" level=info msg="API reload complete" prefix=main
time="Jul 05 16:34:12" level=debug msg="Active Instance is: fed0f5f8-349c-4242-9e4d-9608f223cfbc" prefix=host-check-mgr
time="Jul 05 16:34:12" level=debug msg="--- I am: a8530858-f366-40d0-a703-55a10b590295" prefix=host-check-mgr
time="Jul 05 16:34:12" level=debug msg="New master found, no tests running" prefix=host-check-mgr
time="Jul 05 16:34:12" level=info msg="[HOST CHECKER] Stopping poller"
time="Jul 05 16:34:14" level=debug msg="[HOST CHECKER] Host list reset"
time="Jul 05 16:34:22" level=debug msg="Error trying to get value:redis: nil"
time="Jul 05 16:34:22" level=debug msg="No Primary instance found, assuming control" prefix=host-check-mgr
time="Jul 05 16:34:22" level=info msg="Starting Poller" prefix=host-check-mgr
time="Jul 05 16:34:22" level=debug msg="---> Initialising checker" prefix=host-check-mgr
time="Jul 05 16:34:22" level=debug msg="[HOST CHECKER] Config:TriggerLimit: 3"
time="Jul 05 16:34:22" level=debug msg="[HOST CHECKER] Config:Timeout: ~10"
time="Jul 05 16:34:22" level=debug msg="[HOST CHECKER] Config:WorkerPool: 16"
time="Jul 05 16:34:22" level=debug msg="[HOST CHECKER] Init complete"
time="Jul 05 16:34:22" level=debug msg="---> Starting checker" prefix=host-check-mgr
time="Jul 05 16:34:22" level=debug msg="[HOST CHECKER] Starting..."
time="Jul 05 16:34:22" level=debug msg="[HOST CHECKER] Check loop started..."
time="Jul 05 16:34:22" level=debug msg="[HOST CHECKER] Host reporter started..."
time="Jul 05 16:34:22" level=debug msg="---> Checker started." prefix=host-check-mgr
time="Jul 05 16:34:26" level=debug msg=Started api_id=graphql api_name="GraphQL API" mw=VersionCheck org_id= origin=127.0.0.1 path="/api/" ts=1657038866104132352
time="Jul 05 16:34:26" level=debug msg=Finished api_id=graphql api_name="GraphQL API" code=200 mw=VersionCheck ns=51068 org_id= origin=127.0.0.1 path="/api/"
time="Jul 05 16:34:26" level=debug msg=Started api_id=graphql api_name="GraphQL API" mw=CoProcessMiddleware org_id= origin=127.0.0.1 path="/api/" ts=1657038866104199077
time="Jul 05 16:34:26" level=debug msg="CoProcess Request, HookType: Pre" api_id=graphql api_name="GraphQL API" mw=CoProcessMiddleware org_id= origin=127.0.0.1 path="/api/"
time="Jul 05 16:34:26" level=info msg="PreHook is called" prefix=python
2022/07/05 16:34:26 http: panic serving 127.0.0.1:57040: runtime error: invalid memory address or nil pointer dereference
goroutine 259 [running]:
net/http.(*conn).serve.func1(0xc0008c92c0)
	/usr/local/go/src/net/http/server.go:1801 +0x147
panic(0x2276a80, 0x3480ac0)
	/usr/local/go/src/runtime/panic.go:975 +0x47a
github.com/TykTechnologies/tyk/storage.(*RedisController).Connected(...)
	/go/src/github.com/TykTechnologies/tyk/storage/redis_controller.go:63
github.com/TykTechnologies/tyk/storage.(*RedisCluster).up(0xc001123580, 0xc000478724, 0xc001123538)
	/go/src/github.com/TykTechnologies/tyk/storage/redis_cluster.go:159 +0x2a
github.com/TykTechnologies/tyk/storage.(*RedisCluster).GetKey(0xc001123580, 0xc000478724, 0x5, 0xc000640a02, 0xc00118a000, 0x994, 0x994)
	/go/src/github.com/TykTechnologies/tyk/storage/redis_cluster.go:167 +0x2f
github.com/TykTechnologies/tyk/gateway.TykGetData(0x7f315408ecb0, 0x0)
	/go/src/github.com/TykTechnologies/tyk/gateway/coprocess_api.go:38 +0x73
github.com/TykTechnologies/tyk/gateway._cgoexpwrap_53afb4ba8787_TykGetData(0x7f315408ecb0, 0x0)
	_cgo_gotypes.go:88 +0x65
github.com/TykTechnologies/tyk/dlpython._Cfunc_PyObject_CallObject(0x7f315408a040, 0x7f3154105f40, 0x0)
	_cgo_gotypes.go:379 +0x4e
github.com/TykTechnologies/tyk/dlpython.PyObject_CallObject(...)
	/go/src/github.com/TykTechnologies/tyk/dlpython/binding.go:187
github.com/TykTechnologies/tyk/dlpython.PyObjectCallObject(0x7f315408a040, 0x7f3154105f40, 0x21e58a0, 0x7f3128001650, 0x0)
	/go/src/github.com/TykTechnologies/tyk/dlpython/helpers.go:113 +0x39
github.com/TykTechnologies/tyk/gateway.(*PythonDispatcher).Dispatch(0xc0004ef790, 0xc0005018c0, 0xc00042c618, 0x6, 0xc000ab4ce8)
	/go/src/github.com/TykTechnologies/tyk/gateway/coprocess_python.go:81 +0x74b
github.com/TykTechnologies/tyk/gateway.(*CoProcessor).Dispatch(0xc001124740, 0xc0005018c0, 0x35a9be0, 0xc000821b00, 0xc0005018c0)
	/go/src/github.com/TykTechnologies/tyk/gateway/coprocess.go:583 +0x7c
github.com/TykTechnologies/tyk/gateway.(*CoProcessMiddleware).ProcessRequest(0xc0001faba0, 0x2800420, 0xc00067e000, 0xc00001a400, 0x0, 0x0, 0x206da29, 0xc000821b00, 0x27fcee0)
	/go/src/github.com/TykTechnologies/tyk/gateway/coprocess.go:359 +0x5a9
github.com/TykTechnologies/tyk/gateway.TraceMiddleware.ProcessRequest(0x2817d40, 0xc0001faba0, 0x2800420, 0xc00067e000, 0xc00001a400, 0x0, 0x0, 0x0, 0x0, 0x0)
	/go/src/github.com/TykTechnologies/tyk/gateway/middleware.go:65 +0x293
github.com/TykTechnologies/tyk/gateway.(*Gateway).createMiddleware.func1.1(0x2800420, 0xc00067e000, 0xc00001a400)
	/go/src/github.com/TykTechnologies/tyk/gateway/middleware.go:130 +0x55f
net/http.HandlerFunc.ServeHTTP(0xc000332230, 0x2800420, 0xc00067e000, 0xc00001a400)
	/usr/local/go/src/net/http/server.go:2042 +0x44
github.com/TykTechnologies/tyk/gateway.(*Gateway).createMiddleware.func1.1(0x2800420, 0xc00067e000, 0xc00001a400)
	/go/src/github.com/TykTechnologies/tyk/gateway/middleware.go:165 +0xf9c
net/http.HandlerFunc.ServeHTTP(0xc000332280, 0x2800420, 0xc00067e000, 0xc00001a400)
	/usr/local/go/src/net/http/server.go:2042 +0x44
github.com/rs/cors.(*Cors).Handler.func1(0x2800420, 0xc00067e000, 0xc00001a400)
	/go/src/github.com/rs/cors/cors.go:219 +0x1b9
net/http.HandlerFunc.ServeHTTP(0xc0002e6420, 0x2800420, 0xc00067e000, 0xc00001a400)
	/usr/local/go/src/net/http/server.go:2042 +0x44
github.com/gorilla/mux.(*Router).ServeHTTP(0xc000192e40, 0x2800420, 0xc00067e000, 0xc00001a200)
	/go/src/github.com/gorilla/mux/mux.go:210 +0xd3
github.com/TykTechnologies/tyk/gateway.(*handleWrapper).ServeHTTP(0xc000010620, 0x2800420, 0xc00067e000, 0xc00001a200)
	/go/src/github.com/TykTechnologies/tyk/gateway/proxy_muxer.go:54 +0x16b
golang.org/x/net/http2/h2c.h2cHandler.ServeHTTP(0x27d22a0, 0xc000010620, 0xc0000a2540, 0x2800420, 0xc00067e000, 0xc00001a200)
	/go/src/golang.org/x/net/http2/h2c/h2c.go:104 +0x437
github.com/TykTechnologies/tyk/gateway.(*h2cWrapper).ServeHTTP(0xc0002d7d60, 0x2800420, 0xc00067e000, 0xc00001a200)
	/go/src/github.com/TykTechnologies/tyk/gateway/proxy_muxer.go:42 +0x52
net/http.serverHandler.ServeHTTP(0xc0003f56c0, 0x2800420, 0xc00067e000, 0xc00001a200)
	/usr/local/go/src/net/http/server.go:2843 +0xa3
net/http.(*conn).serve(0xc0008c92c0, 0x28071a0, 0xc000640700)
	/usr/local/go/src/net/http/server.go:1925 +0x8ad
created by net/http.(*Server).Serve
	/usr/local/go/src/net/http/server.go:2969 +0x36c
time="Jul 05 16:34:32" level=debug msg="Primary instance set, I am master" prefix=host-check-mgr

My setting:

tyk-gateway OSS v4.1.0-rc15

I’m using an official Docker image in minikube.

tyk.conf:

{
  "listen_port": 8080,
  "secret": "secret",
  "template_path": "/opt/tyk-gateway/templates",
  "tyk_js_path": "/opt/tyk-gateway/js/tyk.js",
  "middleware_path": "/opt/tyk-gateway/middleware",
  "use_db_app_configs": false,
  "app_path": "/opt/tyk-gateway/apps/",
  "storage": {
    "type": "redis",
    "host": "redis",
    "port": 6379,
    "username": "",
    "password": "",
    "database": 0,
    "optimisation_max_idle": 2000,
    "optimisation_max_active": 4000,
    "enable_cluster": false
  },
  "enable_analytics": false,
  "analytics_config": {
    "type": "csv",
    "csv_dir": "/tmp",
    "mongo_url": "",
    "mongo_db_name": "",
    "mongo_collection": "",
    "purge_delay": -1,
    "ignored_ips": []
  },
  "health_check": {
    "enable_health_checks": false
  },
  "optimisations_use_async_session_write": true,
  "enable_non_transactional_rate_limiter": true,
  "enable_sentinel_rate_limiter": false,
  "enable_redis_rolling_limiter": false,
  "allow_master_keys": false,
  "policies": {
    "policy_source": "mongo",
    "policy_path": "/opt/tyk-gateway/policies",
    "policy_record_name1": "/opt/tyk-gateway/policies/policies.json"
  },
  "hash_keys": true,
  "close_connections": false,
  "http_server_options": {
    "enable_websockets": true
  },
  "allow_insecure_configs": false,
  "coprocess_options": {
    "enable_coprocess": true,
    "python_path_prefix": "/opt/tyk-gateway",
    "coprocess_grpc_server": ""
  },
  "enable_bundle_downloader": true,
  "bundle_base_url": "http://tyk-gateway-mw-bundles/",
  "global_session_lifetime": 100,
  "force_global_session_lifetime": false,
  "max_idle_connections_per_host": 500,
  "control_api_port": 8081
}

Python middleware code:

from tyk.decorators import *
from gateway import TykGateway as tyk


@Hook
def PreHook(request, session, spec):
    tyk.log("PreHook is called", "info")

    v = tyk.get_data('a_key')
    tyk.log("v=" + v, "info")

    return request, session

Please send any GraphQL request to /api/ URL to reproduce the issue.

2

API definition (graphql.json):

{
  "name": "GraphQL API",
  "expiration": "2099-12-31 23:59",
  "slug": "",
  "listen_port": 0,
  "protocol": "",
  "enable_proxy_protocol": false,
  "api_id": "graphql",
  "org_id": "",
  "use_keyless": false,
  "use_oauth2": false,
  "use_openid": false,
  "openid_options": {
    "providers": null,
    "segregate_by_client": false
  },
  "oauth_meta": {
    "allowed_access_types": null,
    "allowed_authorize_types": null,
    "auth_login_redirect": ""
  },
  "auth": {
    "name": "",
    "use_param": false,
    "param_name": "",
    "use_cookie": false,
    "cookie_name": "",
    "disable_header": false,
    "auth_header_name": "",
    "use_certificate": false,
    "validate_signature": false,
    "signature": {
      "algorithm": "",
      "header": "",
      "use_param": false,
      "param_name": "",
      "secret": "",
      "allowed_clock_skew": 0,
      "error_code": 0,
      "error_message": ""
    }
  },
  "auth_configs": {
    "authToken": {
      "name": "",
      "use_param": false,
      "param_name": "",
      "use_cookie": false,
      "cookie_name": "",
      "disable_header": false,
      "auth_header_name": "Authorization",
      "use_certificate": false,
      "validate_signature": false,
      "signature": {
        "algorithm": "",
        "header": "",
        "use_param": false,
        "param_name": "",
        "secret": "",
        "allowed_clock_skew": 0,
        "error_code": 0,
        "error_message": ""
      }
    }
  },
  "use_basic_auth": false,
  "basic_auth": {
    "disable_caching": false,
    "cache_ttl": 0,
    "extract_from_body": false,
    "body_user_regexp": "",
    "body_password_regexp": ""
  },
  "use_mutual_tls_auth": false,
  "client_certificates": null,
  "upstream_certificates": null,
  "pinned_public_keys": null,
  "enable_jwt": true,
  "use_standard_auth": false,
  "use_go_plugin_auth": false,
  "enable_coprocess_auth": false,
  "jwt_signing_method": "hmac",
  "jwt_source": "",
  "jwt_identity_base_field": "",
  "jwt_client_base_field": "",
  "jwt_policy_field_name": "",
  "jwt_default_policies": [
    "graphql-default"
  ],
  "jwt_issued_at_validation_skew": 0,
  "jwt_expires_at_validation_skew": 0,
  "jwt_not_before_validation_skew": 0,
  "jwt_skip_kid": false,
  "scopes": {
    "jwt": {
      "scope_claim_name": "",
      "scope_to_policy": null
    },
    "oidc": {
      "scope_claim_name": "",
      "scope_to_policy": null
    }
  },
  "jwt_scope_to_policy_mapping": {},
  "jwt_scope_claim_name": "sub",
  "notifications": {
    "shared_secret": "",
    "oauth_on_keychange_url": ""
  },
  "enable_signature_checking": false,
  "hmac_allowed_clock_skew": 0,
  "hmac_allowed_algorithms": null,
  "request_signing": {
    "is_enabled": false,
    "secret": "",
    "key_id": "",
    "algorithm": "",
    "header_list": null,
    "certificate_id": "",
    "signature_header": ""
  },
  "base_identity_provided_by": "",
  "definition": {
    "enabled": false,
    "name": "",
    "default": "",
    "location": "",
    "key": "",
    "strip_path": false,
    "strip_versioning_data": false,
    "versions": null
  },
  "version_data": {
    "not_versioned": true,
    "default_version": "",
    "versions": {
      "Default": {
        "name": "Default",
        "expires": "",
        "paths": {
          "ignored": null,
          "white_list": null,
          "black_list": null
        },
        "use_extended_paths": true,
        "extended_paths": {},
        "global_headers": null,
        "global_headers_remove": null,
        "global_response_headers": null,
        "global_response_headers_remove": null,
        "ignore_endpoint_case": false,
        "global_size_limit": 0,
        "override_target": ""
      }
    }
  },
  "uptime_tests": {
    "check_list": null,
    "config": {
      "expire_utime_after": 0,
      "service_discovery": {
        "use_discovery_service": false,
        "query_endpoint": "",
        "use_nested_query": false,
        "parent_data_path": "",
        "data_path": "",
        "port_data_path": "",
        "target_path": "",
        "use_target_list": false,
        "cache_timeout": 0,
        "endpoint_returns_list": false
      },
      "recheck_wait": 0
    }
  },
  "proxy": {
    "preserve_host_header": false,
    "listen_path": "/api/",
    "disable_strip_slash": false,
    "strip_listen_path": true,
    "enable_load_balancing": false,
    "target_list": null,
    "check_host_against_uptime_tests": false,
    "service_discovery": {
      "use_discovery_service": false,
      "query_endpoint": "",
      "use_nested_query": false,
      "parent_data_path": "",
      "data_path": "",
      "port_data_path": "",
      "target_path": "",
      "use_target_list": false,
      "cache_timeout": 0,
      "endpoint_returns_list": false
    },
    "transport": {
      "ssl_insecure_skip_verify": false,
      "ssl_ciphers": null,
      "ssl_min_version": 0,
      "ssl_max_version": 0,
      "ssl_force_common_name_check": false,
      "proxy_url": ""
    }
  },
  "disable_rate_limit": false,
  "disable_quota": false,
  "custom_middleware": {
    "pre": [
      {
        "name": "PreHook",
        "path": "",
        "require_session": false,
        "raw_body_only": false
      }
    ],
    "post": null,
    "post_key_auth": null,
    "auth_check": {
      "name": "",
      "path": "",
      "require_session": false,
      "raw_body_only": false
    },
    "response": null,
    "driver": "python",
    "id_extractor": {
      "extract_from": "",
      "extract_with": "",
      "extractor_config": null
    }
  },
  "custom_middleware_bundle": "graphql.zip",
  "cache_options": {
    "cache_timeout": 0,
    "enable_cache": false,
    "cache_all_safe_requests": false,
    "cache_response_codes": null,
    "enable_upstream_cache_control": false,
    "cache_control_ttl_header": "",
    "cache_by_headers": null
  },
  "session_lifetime": 0,
  "active": true,
  "internal": false,
  "auth_provider": {
    "name": "",
    "storage_engine": "",
    "meta": null
  },
  "session_provider": {
    "name": "",
    "storage_engine": "",
    "meta": null
  },
  "event_handlers": {
    "events": null
  },
  "enable_batch_request_support": false,
  "enable_ip_whitelisting": false,
  "allowed_ips": null,
  "enable_ip_blacklisting": false,
  "blacklisted_ips": null,
  "dont_set_quota_on_create": false,
  "expire_analytics_after": 0,
  "response_processors": null,
  "CORS": {
    "enable": true,
    "allowed_origins": [
      "*"
    ],
    "allowed_methods": [
      "POST"
    ],
    "allowed_headers": [
      "Origin",
      "Content-Type",
      "Accept",
      "Authorization"
    ],
    "exposed_headers": [],
    "allow_credentials": false,
    "max_age": 3600,
    "options_passthrough": false,
    "debug": false
  },
  "domain": "",
  "certificates": null,
  "do_not_track": false,
  "tags": null,
  "enable_context_vars": false,
  "config_data": null,
  "tag_headers": null,
  "global_rate_limit": {
    "rate": 0,
    "per": 0
  },
  "strip_auth_data": false,
  "enable_detailed_recording": false,
  "graphql": {
    "schema": "type Query {}",
    "enabled": true,
    "engine": {
      "field_configs": [],
      "data_sources": []
    },
    "type_field_configurations": [],
    "execution_mode": "supergraph",
    "proxy": {
      "auth_headers": {}
    },
    "subgraph": {
      "sdl": ""
    },
    "supergraph": {
      "updated_at": "2022-03-11T16:08:13.774Z",
      "subgraphs": [
      ],
      "merged_sdl": "type Query {}",
      "global_headers": {
        "Authorization": "{{.request.headers.Authorization}}"
      }
    },
    "version": "2",
    "playground": {
      "enabled": true,
      "path": "/playground"
    },
    "last_schema_update": "2022-03-11T16:08:13.774Z"
  }
}
3

Can you try removing this section in the API definition and trying again?

If it still fails then can you share the manifest file?

4

Hello @Olu

Removing custom_middleware from my API definition did not help. I still see an empty response from Tyk and runtime error in logs.

Here’s my plugin manifest:

{
  "file_list": [
    "middleware.py"
  ],
  "custom_middleware": {
    "pre": [
      {
        "name": "PreHook"
      }
    ],
    "driver": "python"
  }
}
5

@Andrey_Nado, I seem to be having the same gateway panic issue or Release Candidate versions. I have asked internally and would get back to you.

1 Like
6

Hello @Olu!

The issue still persists in tyk gateway v4.1.0 (recently released).

Is there a bug in my Python middleware or configuration?

7

Thanks for double checking.

Is there a bug in my Python middleware or configuration?

No I don’t think so. If you were to check it with 4.0.0 and below, it should work fine.

Can you check that and also share your python version?

8

I am having this same issue, I am using the 3.9 python version. Can anyone help me?

9

Hi @Lohanna_Sarah,

Welcome to the community :tada:

Are you okay to use any of Tyk Gateway 3.1.2 or 4.0.0? Those versions don’t have this issue.

Alternatively, you may use a Golang plugin. See here: Golang plugin use redis data cache

Some information on your usecase and scenario will be helpful too.

10

Ok, I will try the 4.0.0 version.

11

Hey @Lohanna_Sarah, just wanted to check if it works for you now?

12

Hi, I’m getting the same error in tyk 5.0.0. Is there any fix other than downgrading to 4.0.0 or using Go?

13

@bls Sorry about this.

There isn’t any other fix at the moment. We will update this thread once there is an update.

14

Is there any fix for this in progress?

15

Unfortunately, this is still in the backlog.

The alternative is to make a separate connection to Redis and then modify the key that way

16

This issue is now fixed in v5.0.12. Excerpt from release notes below

Fixed a bug where the Gateway could crash when using custom Python plugins that access the Redis storage. The Tyk Python API methods store_data and get_data could fail due to connection issues with the Redis. With this fix, the Redis connection will be created if required, avoiding the crash.