Tyk with custom middleware taking long to become ready when running in CloudRun

Support
,
1

We run tyk in CloudRun, our tyk api definitions custom middleware defined

  "domain": xxxxx",
  "custom_middleware_bundle": "gcp-xxxx-v7.zip",
  "proxy": {

we realised for some reason our tyk container takes up to 10min to become ready

what’s strange is, it seems the logs started around 2023-04-05T15:43:00+10:00

time="Apr 05 05:43:14" level=info msg="Tyk API Gateway 4.3.3" prefix=main
time="Apr 05 05:43:14" level=warning msg="Insecure configuration allowed" config.allow_insecure_configs=true prefix=checkup

then stopped at a point at 2023-04-05T15:44:24.918+10:00 for 8 min,

where it’s saying

time="Apr 05 05:44:16" level=info msg="Loading module: '0cba8414a918ee0e65e0b53a210b9055'" prefix=python

so it’s loading module which i presume is our custom middleware, then at 2023-04-05T05:52:01+10:00 it started to pump logs

time="Apr 05 05:52:01" level=error msg="error while closing file /opt/tyk-gateway/apps/xxxx/account_api_xxxxxxx.json"

then finally at 2023-04-05T05:52:26+10:00, it has loaded all the api successfully

time="Apr 05 05:52:26" level=info msg="API bind on custom port:0" prefix=main

we don’t seem to experience this in local docker-compose run, which all api definitions was loaded quite fast winthin 10 seconds

2

Hi and welcome to the community :tada: @zye-carma,

Regarding the 1st issue, my first guess is that it could be the fetching of the bundle taking that long. Can you set your log_level to debug, and restart the gateway? Please share the full gateway logs from its startup.

The second one - error closing file - appears to be site-specific as you’ve found that it’s not the case with docker-compose. If everything works well, you might be able to ignore it. For now, let’s focus on the first issue.

Looking forward to your response

3

Cheers @Ubong, attached is a more detailed logs, (sry due to message limit, i couldn’t paste the full log)

time="Apr 05 05:52:01" level=info msg="Loading API Specification from /opt/tyk-gateway/apps/beta/xxxx.json"
time="Apr 05 05:52:01" level=error msg="error while closing file /opt/tyk-gateway/apps/beta/xxxx.json"
time="Apr 05 05:52:01" level=info msg="----> Using bundle: gcp-auth-v7.zip" prefix=main
time="Apr 05 05:52:01" level=info msg="----> Loading bundle: gcp-auth-v7.zip" prefix=main
time="Apr 05 05:52:01" level=info msg="Loading existing bundle: gcp-auth-v7.zip" prefix=main
time="Apr 05 05:52:01" level=info msg="Loading API Specification from /opt/tyk-gateway/apps/beta/xxxx.json"
time="Apr 05 05:52:01" level=error msg="error while closing file /opt/tyk-gateway/apps/beta/xxxx.json"
time="Apr 05 05:52:01" level=info msg="----> Using bundle: gcp-auth-v7.zip" prefix=main
time="Apr 05 05:52:01" level=info msg="----> Loading bundle: gcp-auth-v7.zip" prefix=main
time="Apr 05 05:52:01" level=info msg="Loading existing bundle: gcp-auth-v7.zip" prefix=main
time="Apr 05 05:52:01" level=info msg="Loading API Specification from /opt/tyk-gateway/apps/beta/xxxx.json"
time="Apr 05 05:52:01" level=error msg="error while closing file /opt/tyk-gateway/apps/beta/xxxx.json"
time="Apr 05 05:44:24" level=info msg="Loading module: '0cba8414a918ee0e65e0b53a210b9055'" prefix=python
time="Apr 05 05:44:24" level=info msg="Python dispatcher was initialized" prefix=coprocess
time="Apr 05 05:44:24" level=info msg="Initializing dispatcher" prefix=python
time="Apr 05 05:44:16" level=info msg="Loading module: '0cba8414a918ee0e65e0b53a210b9055'" prefix=python
time="Apr 05 05:44:16" level=info msg="Python dispatcher was initialized" prefix=coprocess
time="Apr 05 05:44:16" level=info msg="Initializing dispatcher"

the part i’m super confused is at

time="Apr 05 05:52:01" level=error msg="error while closing file /opt/tyk-gateway/apps/beta/xxxx.json"
time="Apr 05 05:44:24" level=info msg="Loading module: '0cba8414a918ee0e65e0b53a210b9055'" prefix=python

where is stopped for 9 min, i have a feeling tyk doesn’t actually load the api module until the first time the path is called

4

Hi,

This is a really difficult question to help with without access to Cloudrun. The only things I can suggest are:

  • Running the gateway with profiling enabled and capturing different profiles to see what’s happening during the time it’s paused (if possible). While pprof does produce a web interface, a better way to download profiles for analysis is like thiswget -O profile.dmp --no-check-certificate https://gaewayURL/debug/pprof/profile?seconds=2 The profile can then be analysed using https://pprofweb.evanjones.ca/

  • Building and running an instrumented version of the gateway to try and see where it’s hanging. What I mean is just putting log statements to try and track what the gateway is up to.

  • Using something like Delve to do an interactive debug of the running process and step through what’s happening. I’d suggest setting a breakpoint here and stepping forward from that

i have a feeling tyk doesn’t actually load the api module until the first time the path is called

This isn’t the case. Tyk loads all the APIs and policies during startup (or hot reload) and activates them all at the same time.

Sorry I couldn’t be more help.
Pete

5

@zye-carma did you ever get this issue resolved. We are interested in using cloudrun as well to run serverless instance of tyk and interested to see if you were successful in the end?