Python bundles get purged after reloading endpoints

arsakiyo · May 17, 2017, 11:21am

I am exploring different api managers and for this case, I picked your docker installation version for a test.

While developing a custom python auth plugin, I found that I was receiving a log message “Can’t dispatch ‘MyMiddleware’, hook is not defined.”
Source is clear, this message is thrown when there is no hook in hook_table with the key ‘MyMiddleware’

This is the trace I am getting from my gateway logs:

tyk_gateway_1    | time="May 17 10:41:55" level=info msg="Reloading endpoints" 
tyk_gateway_1    | time="May 17 10:41:55" level=info msg="Reload queued" 
tyk_gateway_1    | time="May 17 10:41:55" level=info msg="Initiating reload" 
tyk_gateway_1    | time="May 17 10:41:55" level=info msg="Loading policies" 
tyk_gateway_1    | time="May 17 10:41:55" level=info msg="Using Policies from Dashboard Service" 
tyk_gateway_1    | time="May 17 10:41:55" level=info msg="Mutex lock acquired... calling" 
tyk_gateway_1    | time="May 17 10:41:55" level=info msg="Calling dashboard service for policy list" 
tyk_gateway_1    | time="May 17 10:41:55" level=info msg="Processing policy list" 
tyk_gateway_1    | time="May 17 10:41:55" level=info msg="--> Processing policy ID: 591c0890b6305d0001f63c43" 
tyk_gateway_1    | time="May 17 10:41:55" level=info msg="Detected 4 APIs" 
tyk_gateway_1    | time="May 17 10:41:55" level=info msg="Preparing new router" 
tyk_gateway_1    | time="May 17 10:41:55" level=info msg="Initialising Tyk REST API Endpoints" 
tyk_gateway_1    | time="May 17 10:41:55" level=info msg="Loading API configurations." 
tyk_gateway_1    | time="May 17 10:41:55" level=info msg="Tracking hostname" api_name="Portal Assets" domain=www.tyk-portal-test.com 
tyk_gateway_1    | time="May 17 10:41:55" level=info msg="Tracking hostname" api_name=MyApi domain="(no host)" 
tyk_gateway_1    | time="May 17 10:41:55" level=info msg="Tracking hostname" api_name="Portal API" domain=www.tyk-portal-test.com 
tyk_gateway_1    | time="May 17 10:41:55" level=info msg="Tracking hostname" api_name=Portal domain=www.tyk-portal-test.com 
tyk_gateway_1    | time="May 17 10:41:55" level=info msg="Loading API" api_name="Portal API" 
tyk_gateway_1    | time="May 17 10:41:55" level=info msg="Checking security policy: Open" api_name="Portal API" 
tyk_gateway_1    | time="May 17 10:41:55" level=info msg="Loading API" api_name=Portal 
tyk_gateway_1    | time="May 17 10:41:55" level=info msg="Checking security policy: Open" api_name=Portal 
tyk_gateway_1    | time="May 17 10:41:55" level=info msg="Loading API" api_name="Portal Assets" 
tyk_gateway_1    | time="May 17 10:41:55" level=info msg="Checking security policy: Open" api_name="Portal Assets" 
tyk_gateway_1    | time="May 17 10:41:55" level=info msg="Loading API" api_name=MyApi 
tyk_gateway_1    | time="May 17 10:41:55" level=info msg="----> Fetching Bundle: my-bundle.zip" 
tyk_gateway_1    | time="May 17 10:41:55" level=info msg="----> Loading bundle: my-bundle.zip" 
tyk_gateway_1    | time="May 17 10:41:55" level=info msg="----> Verifying bundle: my-bundle.zip" 
tyk_gateway_1    | time="May 17 10:41:55" level=info msg="----> Bundle is valid, adding to spec: my-bundle.zip" 
tyk_gateway_1    | time="May 17 10:41:55" level=info msg="Loading module: 'myMiddleware'" 
tyk_gateway_1    | time="May 17 10:41:55" level=info msg="Checking security policy: CoProcess Plugin" api_name=MyApi 
tyk_statics_1    | 172.18.0.2 - - [17/May/2017:10:41:55 +0000] "GET /my-bundle.zip HTTP/1.1" 200 968 "-" "Go-http-client/1.1" "-"
tyk_gateway_1    | time="May 17 10:41:56" level=info msg="Processed and listening on: /portal-assets/{rest:.*}" 
tyk_gateway_1    | time="May 17 10:41:56" level=info msg="Processed and listening on: /my-api/{rest:.*}" 
tyk_gateway_1    | time="May 17 10:41:56" level=info msg="Processed and listening on: /portal-api/{rest:.*}" 
tyk_gateway_1    | time="May 17 10:41:56" level=info msg="Processed and listening on: /portal/{rest:.*}" 
tyk_gateway_1    | time="May 17 10:41:56" level=info msg="Loading uptime tests..." 
tyk_gateway_1    | time="May 17 10:41:56" level=info msg="Initialised API Definitions" 
tyk_gateway_1    | time="May 17 10:41:56" level=info msg="API reload complete" 
tyk_gateway_1    | time="May 17 10:41:56" level=info msg="Initiating coprocess reload" 
tyk_gateway_1    | time="May 17 10:41:56" level=info msg="Reloading middlewares" 
tyk_gateway_1    | time="May 17 10:41:56" level=info msg="Reloading event handlers and middlewares." 
tyk_gateway_1    | time="May 17 10:41:56" level=warning msg="Purging middleware: 'myMiddleware'"

As you can see, the budle gets registered correctly but as a final step, coprocess reload is triggered.
Middleware purge removes all bundles, since they can’t be found in middleware_path.
Middleware load loads all middlewares but no bundles are loaded.
There is missing a load_bundles call, I think it would fix this bug.

Martin · May 17, 2017, 1:12pm

This would be a good question for our plugin expert, cc @matiasb

arsakiyo · May 18, 2017, 11:21am

Any news? Without python plugins I can’t event think on using this Api Gateway.

Martin · May 19, 2017, 4:07am

Hi, apologies for the delayed reply, we’re trying to put together a diagnosis.

Martin · May 19, 2017, 4:14am

@arsakiyo It would really help if you could send us your api definition and how you installed tyk, just so we can try and replicate…

arsakiyo · May 19, 2017, 7:30am

@Martin As I stated in my original post, I am using your docker installation method just for a fast test with some modifications in order to run with python bundle compatibility and add a new nginx for bundle hosting purposes.

Since your docker installation comes with dashboard and database persistence by default I can’t provide my api definition.

Here is a gist with my docker-compose.yml and tyk.conf files: My tyk · GitHub

Greetings,
Raúl

Martin · May 19, 2017, 7:48am

You can click the export button in the API Designer and get the API Definition as JSON downloaded to your disk

Thanks for sharing your compose config.

M.

Martin · May 19, 2017, 7:51am

Also, can you verify in the running container that there are files downloaded to this location in your container? If not, then you may need to create the directory, or change it in the tyk.conf ("middleware_path": "/opt/tyk-gateway/middleware")?

arsakiyo · May 19, 2017, 8:01am

Nice! I could get it exported => app.json · GitHub

Sure they are , I had to create manually the directory middleware/bundles but once directory exists, plugins are downloaded correctly and stored there

docker exec tykquickstart_tyk_gateway_1 ls -la middleware/bundles
total 12
drwxr-xr-x 3 root root 4096 May 19 07:55 .
drwxr-xr-x 5 root root 4096 May 19 07:55 ..
drwxr-xr-x 3 root root 4096 May 19 07:55 1c608d6ba38943996311271c37e8c6fc-auth-bundle-536.zip

Martin · May 19, 2017, 8:15am

Right… so I think the middleware bundles are then extracted, and the reason why the purge happens is because the extracted module can;t be found on the path. So the question is whether the bundles are being put into the correct location.

I may need to try and replicate this, which can take some time :-/

Thanks for the info, leave it with us and we’ll get to the bottom of it…

tom.coates · June 16, 2017, 10:00pm

Any luck with this @Martin/@arsakiyo? I am experience the same thing.

matiasb · June 16, 2017, 10:28pm

Hi, can you share your Tyk logs, when the reload process is triggered?

Also, can you share a list of the contents in middleware/bundles, before and after the reload.

This will be useful for debugging this issue.

Thanks

tom.coates · June 18, 2017, 9:21pm

Hi Matías,

I’ll post the logs/ bundle contents first thing tomorrow morning.

Cheers

tom.coates · June 19, 2017, 8:42am

Hey,

Here are the logs written at the point of hot reloading the gateway.

time="Jun 18 21:25:32" level=info msg="Group reload accepted." status=ok
time="Jun 18 21:25:32" level=info msg="Reloaded URL Structure - Success"
time="Jun 18 21:25:32" level=warning msg="Insecure configuration detected (allowing)!"
time="Jun 18 21:25:32" level=info msg="Reloading endpoints"
time="Jun 18 21:25:32" level=info msg="Reload queued"
time="Jun 18 21:25:32" level=info msg="Initiating reload"
time="Jun 18 21:25:32" level=info msg="Loading policies"
time="Jun 18 21:25:32" level=error msg="Couldn't load policy file: read policies: is a directory"
time="Jun 18 21:25:32" level=info msg="Loading API Specification from /opt/tyk-gateway/apps/c8db77199c094c8847fce41a15e0e773.json"
time="Jun 18 21:25:32" level=info msg="Detected 1 APIs"
time="Jun 18 21:25:32" level=info msg="Preparing new router"
time="Jun 18 21:25:32" level=info msg="Initialising Tyk REST API Endpoints"
time="Jun 18 21:25:32" level=info msg="Loading API configurations."
time="Jun 18 21:25:32" level=info msg="Tracking hostname" api_name=Test domain="(no host)"
time="Jun 18 21:25:32" level=info msg="Loading API" api_name=Test
time="Jun 18 21:25:32" level=info msg="Loading existing bundle: authentication-1.0.2.zip"
time="Jun 18 21:25:32" level=info msg="----> Loading bundle: authentication-1.0.2.zip"
time="Jun 18 21:25:32" level=info msg="----> Using bundle: authentication-1.0.2.zip"
time="Jun 18 21:25:32" level=info msg="Checking security policy: Token" api_name=Test
time="Jun 18 21:25:33" level=info msg="Processed and listening on: /Test/{rest:.*}"
time="Jun 18 21:25:33" level=info msg="Loading uptime tests..."
time="Jun 18 21:25:33" level=info msg="Initialised API Definitions"
time="Jun 18 21:25:33" level=info msg="API reload complete"
time="Jun 18 21:25:33" level=info msg="Initiating coprocess reload"
time="Jun 18 21:25:33" level=info msg="Reloading middlewares"
time="Jun 18 21:25:33" level=info msg="Reloading event handlers and middlewares."
time="Jun 18 21:25:33" level=warning msg="Purging middleware: 'middleware'"

And this is what gets written when hitting the API after the reload.

time="Jun 18 21:26:13" level=error msg="Can't dispatch 'PostMiddleware', hook is not defined."

The new bundles filename had a point release bump between reloads and there was some changes made to the Post middleware but no files were added or removed from the bundle and the manifest.json did not change.

Cheers

matiasb · June 20, 2017, 5:22pm

Thanks, this will be useful for us.

tom.coates · July 12, 2017, 7:37pm

Hey,

Wondering if there has been any progress on this issue?

Cheers

Martin · July 13, 2017, 10:37am

It’s on the agenda to be fixed with the next release

Martin · July 13, 2017, 10:37am

Relevant patch I believe: Python GIL error - #8 by matiasb

jeffrngu · October 11, 2017, 5:36pm

Hi Martin,

I’m running into this exact same problem of middleware getting purged after API reload. Is this issue already fixed? I checked https://github.com/lonelycode/tyk_quickstart.git but didn’t see any updated fix.

Does the patch you mentioned above fix this issue? I’m not seeing the exception stack trace mentioned on that thread.

Now the weird thing is at some point on my set up, I was able to get this python plugin working. Then I switched to java based gRPC plugin and when I switched back to python based plugin, it stopped working. I re-deployed the tyk containers and now I’m stuck with this issue where the python plugin keeps getting un-deployed.

I’m running Tyk containers on Docker similar to the setup mentioned on this post. Any idea how to fix this? If the fix is not available yet, is there a work-around? Please see log below.

Thanks,
-Jeffrey

time=“Oct 11 16:54:12” level=info msg=“Processed and listening on: /portal-assets/{rest:.}"
time=“Oct 11 16:54:12” level=info msg="Processed and listening on: /portal-api/{rest:.}”
time=“Oct 11 16:54:12” level=info msg=“Processed and listening on: /test-api/{rest:.}"
time=“Oct 11 16:54:12” level=info msg="Processed and listening on: /portal/{rest:.}”
time=“Oct 11 16:54:12” level=info msg=“Loading uptime tests…”
time=“Oct 11 16:54:12” level=info msg=“Initialised API Definitions”
time=“Oct 11 16:54:12” level=info msg=“API reload complete”
time=“Oct 11 16:54:12” level=info msg=“Initiating coprocess reload”
time=“Oct 11 16:54:12” level=info msg=“Reloading middlewares”
time=“Oct 11 16:54:12” level=info msg=“Reloading event handlers and middlewares.”
time=“Oct 11 16:54:52” level=info msg=“Reloading endpoints”
time=“Oct 11 16:54:52” level=info msg=“Reload queued”
time=“Oct 11 16:54:52” level=info msg=“Initiating reload”
time=“Oct 11 16:54:52” level=info msg=“Loading policies”
time=“Oct 11 16:54:52” level=info msg=“Using Policies from Dashboard Service”
time=“Oct 11 16:54:52” level=info msg=“Mutex lock acquired… calling”
time=“Oct 11 16:54:52” level=info msg=“Calling dashboard service for policy list”
time=“Oct 11 16:54:52” level=info msg=“Processing policy list”
time=“Oct 11 16:54:52” level=info msg=“Detected 4 APIs”
time=“Oct 11 16:54:52” level=info msg=“Preparing new router”
time=“Oct 11 16:54:52” level=info msg=“Initialising Tyk REST API Endpoints”
time=“Oct 11 16:54:52” level=info msg=“Loading API configurations.”
time=“Oct 11 16:54:52” level=info msg=“Tracking hostname” api_name=“Portal Assets” domain=www.tyk-portal-test.com
time=“Oct 11 16:54:52” level=info msg=“Tracking hostname” api_name=“Portal API” domain=www.tyk-portal-test.com
time=“Oct 11 16:54:52” level=info msg=“Tracking hostname” api_name=“Test API” domain=“(no host)”
time=“Oct 11 16:54:52” level=info msg=“Tracking hostname” api_name=Portal domain=www.tyk-portal-test.com
time=“Oct 11 16:54:52” level=info msg=“Loading API” api_name=“Test API”
time=“Oct 11 16:54:52” level=info msg=“Loading API” api_name=“Portal API”
time=“Oct 11 16:54:52” level=info msg=“Checking security policy: Open” api_name=“Portal API”
time=“Oct 11 16:54:52” level=info msg=“----> Fetching Bundle: python-bundle.zip”
time=“Oct 11 16:54:52” level=info msg=“Loading API” api_name=“Portal Assets”
time=“Oct 11 16:54:52” level=info msg=“Loading API” api_name=Portal
time=“Oct 11 16:54:52” level=info msg=“Checking security policy: Open” api_name=“Portal Assets”
time=“Oct 11 16:54:52” level=info msg=“Checking security policy: Open” api_name=Portal
time=“Oct 11 16:54:52” level=info msg=“----> Loading bundle: python-bundle.zip”
time=“Oct 11 16:54:52” level=info msg=“----> Verifying bundle: python-bundle.zip”
time=“Oct 11 16:54:52” level=info msg=“----> Bundle is valid, adding to spec: python-bundle.zip”
time=“Oct 11 16:54:52” level=info msg=“Checking security policy: CoProcess Plugin” api_name=“Test API”
time=“Oct 11 16:54:52” level=info msg=“Loading module: ‘middleware’”
time=“Oct 11 16:54:53” level=info msg=“Processed and listening on: /portal-assets/{rest:.}"
time=“Oct 11 16:54:53” level=info msg="Processed and listening on: /portal-api/{rest:.}”
time=“Oct 11 16:54:53” level=info msg=“Processed and listening on: /test-api/{rest:.}"
time=“Oct 11 16:54:53” level=info msg="Processed and listening on: /portal/{rest:.}”
time=“Oct 11 16:54:53” level=info msg=“Loading uptime tests…”
time=“Oct 11 16:54:53” level=info msg=“Initialised API Definitions”
time=“Oct 11 16:54:53” level=info msg=“API reload complete”
time=“Oct 11 16:54:53” level=info msg=“Initiating coprocess reload”
time=“Oct 11 16:54:53” level=info msg=“Reloading middlewares”
time=“Oct 11 16:54:53” level=info msg=“Reloading event handlers and middlewares.”
time=“Oct 11 16:54:53” level=warning msg=“Purging middleware: ‘middleware’”
time=“Oct 11 16:55:28” level=error msg=“Can’t dispatch ‘MyAuthMiddleware’, hook is not defined.”
time=“Oct 11 16:55:28” level=error msg=“request error: Key not authorised” api_id=ce5360c963ac475277a1672ec858635a org_id=59de481c2e7f09000106f0b6 path=“/get” server_name=“http://httpbin.org/” user_id= user_ip=172.18.0.1

jeffrngu · October 11, 2017, 7:51pm

Did some further investigation and noticed the PYTHONPATH is incorrect for the paths to the bundle .zip.

time=“Oct 11 19:28:35” level=info msg=“Setting PYTHONPATH to ‘/opt/tyk-gateway/coprocess/python:/opt/tyk-gateway/middleware/python:/opt/tyk-gateway/event_handlers:/opt/tyk-gateway/coprocess/python/proto:middleware/bundles/ce5360c963ac475277a1672ec858635a-python-bundle.zip’”

The working directory “/opt/tyk-gateway” needs to preceed “middleware/bundles”.

It looks like a bug in the code here https://github.com/TykTechnologies/tyk/blob/master/coprocess_python.go#L293

I never written any code in Go in my life but it seems to me the fix should be something like Fix for incorrect bunddle path in PYTHONPATH · GitHub

The question is how can I try this out on the Docker based Tyk container? I couldn’t find coprocess_python.go on the Tyk gateware container.

Thanks,
-Jeffrey