Potential Race Issue?

Hi Folks,

I have a set of API’s that are created using the Dashboard API, I am using JWT authentication, and I seem to have the entire situation working properly.

However, when I was building and testing the configs, I would run into a problem that would result in the following log entry from the gateway:

time="Mar 27 13:46:48" level=info msg="Attempted access to unauthorised API." api_found=false key="<hidden>" origin=172.20.0.7 path="/log/activity"

and also this response:

{
   "error": "Access to this API has been disallowed"
}

By going to the Dashboard and “updating” the API, the api would register and the traffic would pass through. I tracked all of this down to configuration issues in the JSON, and I got everything working fine on my machine…

When handing this all over to another person on the team, they are having issues that I was seeing previously while using the same config that I have working. Updating in the dashboard seems to solve the problem.

We think this may be due to machine speed. We also had to add a “rest” in the build process between when the mongo container was launched, and when the gateway container was started. While the gateway container does have a retry, it was not long enough and the gateway container would fail as a result.

We were wondering if there is also some kind of latency or race condition that could prevent the registration of an API from becoming available. There doesn’t seem to be any config issues, as we pull the JSON before “updating” and after using the dashboard API, and there is no difference between the output. But the update is doing something that perhaps we should be doing during our build process (which, for the record is a custom system, but not unlike the docker compose process). A reload of everything, perhaps?

Thanks.

Addendum. We removed the white list from the config and the issues disappear (turned off extended_paths). But the results are still inconsistent between different environments.

Hello, do you use on-premise, and if so, which version?

Yes, on premise, and using the container, so whatever is currently shipping in there.

If Gateway can’t fetch latest APIs from the dashboard, it should print some errors to the logs.
Can you attach the full log, which replicates the issue, preferably if you do it with debug output, by passing TYK_LOGLEVEL=debug env variable to container.

Thank you.

I’ll ask my tech to do so in the morning. BTW, removing the whitelist (keeping the ignore) in the extended paths seems to avoid the problem. So we have narrowed the issue to the white list that we were creating. Again, what works on my end doesn’t on his, and we had to add a pause in the process to wait for Mongo to be ready. We suspect some latency issue with Mongo at this time.

Thanks for the help.

I’m currently facing the same issue. On premises configured with Dashboard. Freshly reinstalled instance, 2 apis work without any issues, 3rd added (via import from json) a week later:

time=“Apr 11 06:58:52” level=info msg=“Attempted access to unauthorised API.” api_found=false key=“” origin=10.24.200.35 path=“/api/client”

Though in my case nothing has fixed it. I’ve tried deleting the api and associated policy, but it did not resolve the issue.
If I have to reinstall tyk YET AGAIN to get it working, I’m dropping this software.

Mike,

What solved this for us was to essentially hit “save” (or update) on the API in the dashboard.

There may be something with the JSON/Dashboard API process as it relates to the whitelist, but as I have stated, the mileage varies from machine to machine.

We still owe this thread some logs, the matter has been worked around as we have removed the white list requirement from the API definition. This has allowed the developers to continue working, but it is something that we will turn back on soon. Once we do, we will get some logs to this thread.

I was able to replicate this on a dedicated server. But my solution (updating the API in the gateway) doesn’t do the trick. Any clues in these log entries?

time="Apr 24 20:49:38" level=debug msg="JWT authority is centralised"
time="Apr 24 20:49:38" level=debug msg="Base Field ID set to: 2696a874-48f3-43d8-a6d6-4cd65e558fb4"
time="Apr 24 20:49:38" level=debug msg="JWT Temporary session ID is: 5adf9774d1924300019be6e99121ec1a0fc0082baa2e2bd5dbad2e4f"
time="Apr 24 20:49:38" level=debug msg="Querying local cache"
time="Apr 24 20:49:38" level=debug msg="Querying keystore"
time="Apr 24 20:49:38" level=debug msg="[STORE] Getting WAS: 5adf9774d1924300019be6e99121ec1a0fc0082baa2e2bd5dbad2e4f"
time="Apr 24 20:49:38" level=debug msg="[STORE] Getting: apikey-9170b1a4"
time="Apr 24 20:49:38" level=debug msg="--> Got key"
time="Apr 24 20:49:38" level=debug msg="Key found"
time="Apr 24 20:49:38" level=info msg="Attempted access to unauthorised API." api_found=false key="<hidden>" origin=172.19.0.1 path="/search"
time="Apr 24 20:49:38" level=debug msg="Adding Healthcheck to: 3205d50d8c8f481d74f94d87a28c5860.BlockedRequest"
time="Apr 24 20:49:38" level=debug msg="Val is: -1"
time="Apr 24 20:49:38" level=debug msg="[STORE] SET Raw key is: 5adf9774d1924300019be6e99121ec1a0fc0082baa2e2bd5dbad2e4f"
time="Apr 24 20:49:38" level=debug msg="[STORE] Setting key: apikey-9170b1a4"
time="Apr 24 20:49:38" level=debug msg="Pushing to raw key list: tyk-system-analytics"
time="Apr 24 20:49:38" level=debug msg="Appending to fixed key list: analytics-tyk-system-analytics"
time="Apr 24 20:49:38" level=debug msg="Incrementing raw key: 3205d50d8c8f481d74f94d87a28c5860.BlockedRequest"
time="Apr 24 20:49:38" level=debug msg="keyName is: 3205d50d8c8f481d74f94d87a28c5860.BlockedRequest"
time="Apr 24 20:49:38" level=debug msg="Now is:2018-04-24 20:49:38.831993761 +0000 UTC m=+238.783634975"
time="Apr 24 20:49:38" level=debug msg="Then is: 2018-04-24 20:48:38.831993761 +0000 UTC m=+178.783634975"
time="Apr 24 20:49:38" level=debug msg="Returned: 0"

I don’t understand the api_found=false part of the message. The API is there, listed in the Dashboard. We also have the whitelist tuned off, so should this be turned back on?

I’ll keep testing. Thanks.

Still having trouble with this. I am able to log in to our IDP and get a JWT. But once I try to hit a different endpoint, I get this error:

time="Apr 25 19:26:49" level=info msg="Attempted access to unauthorised API." api_found=false key="<hidden>" origin=71.246.200.99 path="/search"

Right above this entry, in the log, is this:

time="Apr 25 19:25:39" level=info msg="Processed and listening on: /search{rest:.*}"

What doesn’t make sense here is that I have different environments (OSX and Ubuntu) running the same containers, same config and same startup process. Aside form OS, the only other difference I can discern is that one environment is faster than the other.

Anything I can look at in mongo or redis that may shed some light on what is happening?

Thanks.

Are you migrating policies and api definitions between environments? If so, how?

I’m building everything from scratch, using a set of templates and config files (I have constructed a management tool for all of our containers - kinda like a docker compose on steroids).

Also, if I put a 10 second rest between container launches, I seem to have some success. Results are not 100% consistent, so still testing.

Thanks,

To sum up and clode this thread - the access was unauthorised since the policy didnt get the correct api id. It was the object id which is returned in the update api call (/api/apis/) in the “Meta” field.
I have opened a ticket so you can get updated on our progress resolving this issue.

To add on: I had to use the Meta value in the call to: api/apis/<Meta> to pull the api_id value for use in the policy.

1 Like

Yes, I have mentioned that in the ticket to improve our docs. Thanks