HELP! Really weird access denied issue

chanan · September 26, 2020, 12:40am

Hello,

I have a small serverless on AWS gateway project. It has a custom authorizer.
Some of the end points randomly give me a 403 User is not authorized to access this resource.

The very weird thing is that it is random more or less. If I have end point A that works and B that doesn’t work, it will stay like that for the full time it is deployed. If I rerun serverless deploy (no code change) and I retry them they will flip, B will work and A won’t (I think it might be the one I try first will work, not sure).

Further, it doesnt look like it is even hitting the Authorizer. I added some logging there and turned on API gateway logging, and as far as I can tell it is not.

What am I missing here?

The full response headers:

Content-Type: application/json
Content-Length: 60
Connection: keep-alive
Date: Sat, 26 Sep 2020 00:33:22 GMT
x-amzn-RequestId: 80b5e7ec-e56c-4093-980b-5dc8b1dad9ed
x-amzn-ErrorType: AccessDeniedException
x-amz-apigw-id: Tcrc1G35oAMFeCg=
X-Cache: Error from cloudfront
Via: 1.1 3ffea538872bae08b66cb88fd02cc0db.cloudfront.net (CloudFront)
X-Amz-Cf-Pop: ATL56-C2
X-Amz-Cf-Id: QEoTIwqeFMy3LwdXwr0be59fpqB4emDnRSS5JtFeGOQLB1cGoGXLBA==

chanan · September 30, 2020, 10:38pm

This is still happening, and I can reproduce this every time. A bit more info from the logs:

This is the API Gateway log:

2020-09-30T16:30:11.698-06:00	(d6d2866c-a86b-4cc6-bb85-872dd757a6ea) Extended Request Id: Ts4GFGH-IAMF_Kw=

2020-09-30T16:30:11.698-06:00	(d6d2866c-a86b-4cc6-bb85-872dd757a6ea) Starting authorizer: u1rmgm for request: d6d2866c-a86b-4cc6-bb85-872dd757a6ea

2020-09-30T16:30:11.698-06:00	(d6d2866c-a86b-4cc6-bb85-872dd757a6ea) Incoming identity: *************************************************************************************************************************************************************************************************************************************************************************************************************************************************************************************************************************eNhA==

2020-09-30T16:30:11.700-06:00	(d6d2866c-a86b-4cc6-bb85-872dd757a6ea) Using valid authorizer policy for principal: **er

2020-09-30T16:30:11.700-06:00	(d6d2866c-a86b-4cc6-bb85-872dd757a6ea) Successfully completed authorizer execution

2020-09-30T16:30:11.700-06:00	(d6d2866c-a86b-4cc6-bb85-872dd757a6ea) The client is not authorized to perform this operation.

As you can see, it does say the authorizer was called but the client is not authorizer. The problem is the logs for the authorizer dont show a call. The log below shows two calls to a /test end point and both were successful:

2020-09-30T16:27:26.660-06:00	START RequestId: 96ec2853-d3b0-4df1-a502-60527ac03c1a Version: $LATEST

2020-09-30T16:27:26.759-06:00	{"e":1601504846.757,"m":"aws.lambda.enhanced.invocations","t":["region:us-east-1","account_id:495483033202","functionname:marketron-api-alpha-authorizer","resource:marketron-api-alpha-authorizer","cold_start:true","memorysize:1024","runtime:nodejs12.x"],"v":1}

2020-09-30T16:27:27.167-06:00	2020-09-30T22:27:27.166Z 96ec2853-d3b0-4df1-a502-60527ac03c1a INFO [dd.trace_id=1100905375074593644 dd.span_id=1100905375074593644] response :>> Response { size: 0, timeout: 0, [Symbol(Body internals)]: { body: PassThrough { _readableState: [ReadableState], readable: true, _events: [Object: null prototype], _eventsCount: 2, _maxListeners: undefined, _writableState: [WritableState], writable: false, allowHalfOpen: true, _transformState: [Object], [Symbol(kCapture)]: false }, disturbed: false, error: null }, [Symbol(Response internals)]: { url: 'https://api-dev01.marketron.net/Rest/Traffic/api', status: 200, statusText: 'OK', headers: Headers { [Symbol(map)]: [Object: null prototype] }, counter: 0 } }

2020-09-30T16:27:27.167-06:00	2020-09-30T22:27:27.167Z 96ec2853-d3b0-4df1-a502-60527ac03c1a INFO [dd.trace_id=1100905375074593644 dd.span_id=1100905375074593644] Access allowed

2020-09-30T16:27:27.167-06:00	2020-09-30T22:27:27.167Z 96ec2853-d3b0-4df1-a502-60527ac03c1a INFO [dd.trace_id=1100905375074593644 dd.span_id=1100905375074593644] ret :>> { principalId: 'user', policyDocument: { Version: '2012-10-17', Statement: [ [Object] ] } }

2020-09-30T16:27:27.167-06:00	2020-09-30T22:27:27.167Z 96ec2853-d3b0-4df1-a502-60527ac03c1a INFO [dd.trace_id=1100905375074593644 dd.span_id=1100905375074593644] ret.policyDocument.Statement :>> [ { Action: 'execute-api:Invoke', Effect: 'Allow', Resource: 'arn:aws:execute-api:us-east-1:495483033202:uiwbz6e5wa/alpha/GET/api/v1/test' } ]

2020-09-30T16:27:27.169-06:00	{"traces":[[{"trace_id":"0f47339b14a3ab6c","span_id":"1c10fc46c243a181","parent_id":"0f47339b14a3ab6c","name":"http.request","resource":"GET","error":0,"meta":{"_dd.origin":"lambda","service":"marketron-api-alpha-authorizer","span.kind":"client","http.method":"GET","http.url":"https://api-dev01.marketron.net/Rest/Traffic/api","http.status_code":"200"},"metrics":{"_sample_rate":1,"_dd.agent_psr":1,"_sampling_priority_v1":1},"start":1601504846766779100,"duration":386795410,"service":"marketron-api-alpha-authorizer-http-client","type":"http"},{"trace_id":"0f47339b14a3ab6c","span_id":"1a5d51c16a65fa70","parent_id":"0f47339b14a3ab6c","name":"fs.operation","resource":"writeSync","error":0,"meta":{"_dd.origin":"lambda","service":"marketron-api-alpha-authorizer","component":"fs","span.kind":"internal","file.descriptor":"3"},"metrics":{"_sample_rate":1,"_sampling_priority_v1":1},"start":1601504847165774300,"duration":219482,"service":"marketron-api-alpha-authorizer-fs"},{"trace_id":"0f47339b14a3ab6c","span_id":"461b3f2516806f61","parent_id":"0f47339b14a3ab6c","name":"fs.operation","resource":"writeSync","error":0,"meta":{"_dd.origin":"lambda","service":"marketron-api-alpha-authorizer","component":"fs","span.kind":"internal","file.descriptor":"3"},"metrics":{"_sample_rate":1,"_sampling_priority_v1":1},"start":1601504847166063400,"duration":54443,"service":"marketron-api-alpha-authorizer-fs"},{"trace_id":"0f47339b14a3ab6c","span_id":"4efc1d755d6f451e","parent_id":"0f47339b14a3ab6c","name":"fs.operation","resource":"writeSync","error":0,"meta":{"_dd.origin":"lambda","service":"marketron-api-alpha-authorizer","component":"fs","span.kind":"internal","file.descriptor":"3"},"metrics":{"_sample_rate":1,"_sampling_priority_v1":1},"start":1601504847166268700,"duration":40039,"service":"marketron-api-alpha-authorizer-fs"},{"trace_id":"0f47339b14a3ab6c","span_id":"2a77d13a6e21e926","parent_id":"0f47339b14a3ab6c","name":"fs.operation","resource":"writeSync","error":0,"meta":{"_dd.origin":"lambda","service":"marketron-api-alpha-authorizer","component":"fs","span.kind":"internal","file.descriptor":"3"},"metrics":{"_sample_rate":1,"_sampling_priority_v1":1},"start":1601504847166345700,"duration":34424,"service":"marketron-api-alpha-authorizer-fs"},{"trace_id":"0f47339b14a3ab6c","span_id":"7cb3913833acd356","parent_id":"0f47339b14a3ab6c","name":"fs.operation","resource":"writeSync","error":0,"meta":{"_dd.origin":"lambda","service":"marketron-api-alpha-authorizer","component":"fs","span.kind":"internal","file.descriptor":"3"},"metrics":{"_sample_rate":1,"_sampling_priority_v1":1},"start":1601504847166718700,"duration":37842,"service":"marketron-api-alpha-authorizer-fs"},{"trace_id":"0f47339b14a3ab6c","span_id":"0aec96c2483b90f6","parent_id":"0f47339b14a3ab6c","name":"fs.operation","resource":"writeSync","error":0,"meta":{"_dd.origin":"lambda","service":"marketron-api-alpha-authorizer","component":"fs","span.kind":"internal","file.descriptor":"3"},"metrics":{"_sample_rate":1,"_sampling_priority_v1":1},"start":1601504847166787300,"duration":24658,"service":"marketron-api-alpha-authorizer-fs"},{"trace_id":"0f47339b14a3ab6c","span_id":"07b247c326d4eac6","parent_id":"0f47339b14a3ab6c","name":"fs.operation","resource":"writeSync","error":0,"meta":{"_dd.origin":"lambda","service":"marketron-api-alpha-authorizer","component":"fs","span.kind":"internal","file.descriptor":"3"},"metrics":{"_sample_rate":1,"_sampling_priority_v1":1},"start":1601504847167063300,"duration":36865,"service":"marketron-api-alpha-authorizer-fs"},{"trace_id":"0f47339b14a3ab6c","span_id":"575bcea53d2c2f8d","parent_id":"0f47339b14a3ab6c","name":"fs.operation","resource":"writeSync","error":0,"meta":{"_dd.origin":"lambda","service":"marketron-api-alpha-authorizer","component":"fs","span.kind":"internal","file.descriptor":"3"},"metrics":{"_sample_rate":1,"_sampling_priority_v1":1},"start":1601504847167119400,"duration":21240,"service":"marketron-api-alpha-authorizer-fs"},{"trace_id":"0f47339b14a3ab6c","span_id":"0f47339b14a3ab6c","parent_id":"0000000000000000","name":"aws.lambda","resource":"marketron-api-alpha-authorizer","error":0,"meta":{"_dd.origin":"lambda","service":"marketron-api-alpha-authorizer","cold_start":"true","function_arn":"arn:aws:lambda:us-east-1:495483033202:function:marketron-api-alpha-authorizer","function_version":"$LATEST","request_id":"96ec2853-d3b0-4df1-a502-60527ac03c1a","resource_names":"marketron-api-alpha-authorizer"},"metrics":{"_sample_rate":1,"_sampling_priority_v1":1},"start":1601504846761035300,"duration":406185791,"service":"aws.lambda","type":"serverless"}]]}

2020-09-30T16:27:27.179-06:00	END RequestId: 96ec2853-d3b0-4df1-a502-60527ac03c1a

2020-09-30T16:27:27.179-06:00	REPORT RequestId: 96ec2853-d3b0-4df1-a502-60527ac03c1a Duration: 519.03 ms Billed Duration: 600 ms Memory Size: 1024 MB Max Memory Used: 156 MB Init Duration: 1252.62 ms

2020-09-30T16:30:08.414-06:00	START RequestId: a31509c5-0bc0-4cb4-a0d2-89ec07b422d6 Version: $LATEST

2020-09-30T16:30:08.418-06:00	{"e":1601505008.418,"m":"aws.lambda.enhanced.invocations","t":["region:us-east-1","account_id:495483033202","functionname:marketron-api-alpha-authorizer","resource:marketron-api-alpha-authorizer","cold_start:false","memorysize:1024","runtime:nodejs12.x"],"v":1}

2020-09-30T16:30:08.690-06:00	2020-09-30T22:30:08.690Z a31509c5-0bc0-4cb4-a0d2-89ec07b422d6 INFO [dd.trace_id=2504403643472514981 dd.span_id=2504403643472514981] response :>> Response { size: 0, timeout: 0, [Symbol(Body internals)]: { body: PassThrough { _readableState: [ReadableState], readable: true, _events: [Object: null prototype], _eventsCount: 2, _maxListeners: undefined, _writableState: [WritableState], writable: false, allowHalfOpen: true, _transformState: [Object], [Symbol(kCapture)]: false }, disturbed: false, error: null }, [Symbol(Response internals)]: { url: 'https://api-dev01.marketron.net/Rest/Traffic/api', status: 200, statusText: 'OK', headers: Headers { [Symbol(map)]: [Object: null prototype] }, counter: 0 } }

2020-09-30T16:30:08.690-06:00	2020-09-30T22:30:08.690Z a31509c5-0bc0-4cb4-a0d2-89ec07b422d6 INFO [dd.trace_id=2504403643472514981 dd.span_id=2504403643472514981] Access allowed

2020-09-30T16:30:08.691-06:00	2020-09-30T22:30:08.690Z a31509c5-0bc0-4cb4-a0d2-89ec07b422d6 INFO [dd.trace_id=2504403643472514981 dd.span_id=2504403643472514981] ret :>> { principalId: 'user', policyDocument: { Version: '2012-10-17', Statement: [ [Object] ] } }

2020-09-30T16:30:08.691-06:00	2020-09-30T22:30:08.691Z a31509c5-0bc0-4cb4-a0d2-89ec07b422d6 INFO [dd.trace_id=2504403643472514981 dd.span_id=2504403643472514981] ret.policyDocument.Statement :>> [ { Action: 'execute-api:Invoke', Effect: 'Allow', Resource: 'arn:aws:execute-api:us-east-1:495483033202:uiwbz6e5wa/alpha/GET/api/v1/test' } ]

2020-09-30T16:30:08.691-06:00	{"traces":[[{"trace_id":"22c16dd8475f8fa5","span_id":"632cc94463d2e99b","parent_id":"22c16dd8475f8fa5","name":"http.request","resource":"GET","error":0,"meta":{"_dd.origin":"lambda","service":"marketron-api-alpha-authorizer","span.kind":"client","http.method":"GET","http.url":"https://api-dev01.marketron.net/Rest/Traffic/api","http.status_code":"200"},"metrics":{"_sample_rate":1,"_dd.agent_psr":1,"_sampling_priority_v1":1},"start":1601505008419309600,"duration":270247559,"service":"marketron-api-alpha-authorizer-http-client","type":"http"},{"trace_id":"22c16dd8475f8fa5","span_id":"3da50c336b621a7e","parent_id":"22c16dd8475f8fa5","name":"fs.operation","resource":"writeSync","error":0,"meta":{"_dd.origin":"lambda","service":"marketron-api-alpha-authorizer","component":"fs","span.kind":"internal","file.descriptor":"3"},"metrics":{"_sample_rate":1,"_sampling_priority_v1":1},"start":1601505008690327800,"duration":69824,"service":"marketron-api-alpha-authorizer-fs"},{"trace_id":"22c16dd8475f8fa5","span_id":"6e3474385f1089a0","parent_id":"22c16dd8475f8fa5","name":"fs.operation","resource":"writeSync","error":0,"meta":{"_dd.origin":"lambda","service":"marketron-api-alpha-authorizer","component":"fs","span.kind":"internal","file.descriptor":"3"},"metrics":{"_sample_rate":1,"_sampling_priority_v1":1},"start":1601505008690422800,"duration":17090,"service":"marketron-api-alpha-authorizer-fs"},{"trace_id":"22c16dd8475f8fa5","span_id":"0d9c243022f516f4","parent_id":"22c16dd8475f8fa5","name":"fs.operation","resource":"writeSync","error":0,"meta":{"_dd.origin":"lambda","service":"marketron-api-alpha-authorizer","component":"fs","span.kind":"internal","file.descriptor":"3"},"metrics":{"_sample_rate":1,"_sampling_priority_v1":1},"start":1601505008690541600,"duration":56641,"service":"marketron-api-alpha-authorizer-fs"},{"trace_id":"22c16dd8475f8fa5","span_id":"450b319d7f50d225","parent_id":"22c16dd8475f8fa5","name":"fs.operation","resource":"writeSync","error":0,"meta":{"_dd.origin":"lambda","service":"marketron-api-alpha-authorizer","component":"fs","span.kind":"internal","file.descriptor":"3"},"metrics":{"_sample_rate":1,"_sampling_priority_v1":1},"start":1601505008690618600,"duration":21973,"service":"marketron-api-alpha-authorizer-fs"},{"trace_id":"22c16dd8475f8fa5","span_id":"023b2f3923dc1ca9","parent_id":"22c16dd8475f8fa5","name":"fs.operation","resource":"writeSync","error":0,"meta":{"_dd.origin":"lambda","service":"marketron-api-alpha-authorizer","component":"fs","span.kind":"internal","file.descriptor":"3"},"metrics":{"_sample_rate":1,"_sampling_priority_v1":1},"start":1601505008690826500,"duration":27100,"service":"marketron-api-alpha-authorizer-fs"},{"trace_id":"22c16dd8475f8fa5","span_id":"54e48fa3870fedf4","parent_id":"22c16dd8475f8fa5","name":"fs.operation","resource":"writeSync","error":0,"meta":{"_dd.origin":"lambda","service":"marketron-api-alpha-authorizer","component":"fs","span.kind":"internal","file.descriptor":"3"},"metrics":{"_sample_rate":1,"_sampling_priority_v1":1},"start":1601505008690873900,"duration":17822,"service":"marketron-api-alpha-authorizer-fs"},{"trace_id":"22c16dd8475f8fa5","span_id":"5d8644553fe3fdde","parent_id":"22c16dd8475f8fa5","name":"fs.operation","resource":"writeSync","error":0,"meta":{"_dd.origin":"lambda","service":"marketron-api-alpha-authorizer","component":"fs","span.kind":"internal","file.descriptor":"3"},"metrics":{"_sample_rate":1,"_sampling_priority_v1":1},"start":1601505008691110000,"duration":31250,"service":"marketron-api-alpha-authorizer-fs"},{"trace_id":"22c16dd8475f8fa5","span_id":"75409767da804134","parent_id":"22c16dd8475f8fa5","name":"fs.operation","resource":"writeSync","error":0,"meta":{"_dd.origin":"lambda","service":"marketron-api-alpha-authorizer","component":"fs","span.kind":"internal","file.descriptor":"3"},"metrics":{"_sample_rate":1,"_sampling_priority_v1":1},"start":1601505008691158000,"duration":17090,"service":"marketron-api-alpha-authorizer-fs"},{"trace_id":"22c16dd8475f8fa5","span_id":"22c16dd8475f8fa5","parent_id":"0000000000000000","name":"aws.lambda","resource":"marketron-api-alpha-authorizer","error":0,"meta":{"_dd.origin":"lambda","service":"marketron-api-alpha-authorizer","cold_start":"false","function_arn":"arn:aws:lambda:us-east-1:495483033202:function:marketron-api-alpha-authorizer","function_version":"$LATEST","request_id":"a31509c5-0bc0-4cb4-a0d2-89ec07b422d6","resource_names":"marketron-api-alpha-authorizer"},"metrics":{"_sample_rate":1,"_sampling_priority_v1":1},"start":1601505008419006700,"duration":272200439,"service":"aws.lambda","type":"serverless"}]]}

2020-09-30T16:30:08.693-06:00	END RequestId: a31509c5-0bc0-4cb4-a0d2-89ec07b422d6

2020-09-30T16:30:08.693-06:00	REPORT RequestId: a31509c5-0bc0-4cb4-a0d2-89ec07b422d6 Duration: 275.37 ms Billed Duration: 300 ms Memory Size: 1024 MB Max Memory Used: 158 MB

Any ideas why the api gateway would think it called an authorizer when it doesnt look like it did?

chanan · October 1, 2020, 11:26pm

Still beating my head against a wall on this one… So I changed my authorizer to return Allow every single time:

function authorizer(event, context, callback) {
  console.log("event :>> ", event);
  try {
    callback(null, {
      principalId: "user",
      policyDocument: {
        Version: "2012-10-17",
        Statement: [
          {
            Action: "execute-api:Invoke",
            Effect: "Allow",
            Resource: event.methodArn,
          },
        ],
      },
    });
  } catch (e) {
    console.error(e);
  }
}

No way it can get an access denied now, right? Well… apparently it can…

To recap, calling first end point, everything is fine, calling the second end point - it doesnt even call the authorizer.

So, I am starting to suspect - AWS is caching the policy document the method arn and on the second it is checking that document and never calls the authorizer? Can some confirm that is how it works? And if so how do you turn off that behavior? Or tell it to call the authorizer every time when the method is not in the policy document?

onmiddleground · October 2, 2020, 1:32am

I think the problem is the method arn coming into your authorizer Function check is being cached by the API gateway authorizer and that is why the results you have are random. Try changing your method arn code to use a wildcard Instead of the method arn as is when the code validates the policy.

chanan · October 2, 2020, 1:44pm

I used the two examples that are linked off the example ages which do the same:

Both those files take the method arn from event.methodArn.

Regarldess, the autorizer never gets called for a second time.

Sequance:

/test1
Authorizer gets called.
Allow is returned (currently method is set to always return Allow)
/test2
Authorizer is not called again
AWS Api gateway logs (extended logging that can be turned on) shows that the methd is denied (again without calling the authorizer)

chanan · October 2, 2020, 2:48pm

Finally solved!

The answer came from: API Gateway authorization and policy caching

TL;DR: Policies are cached so you either need to set the TTL to 0, so your authorizer gets called each time, or you need to construct a policy document that includes every single end point you have in your API. In my case, it was easy because I want to let the user access everything if they are logged in so my code looks something like this (Note right now set to Allow always, you should of course set to Allow or Deny as needed):

function authorizer(event, context, callback) {
  const ret = {
    principalId: null,
    policyDocument: {
      Version: "2012-10-17",
      Statement: [
        {
          Action: "execute-api:Invoke",
          Effect: "Allow",
          Resource: "arn:aws:execute-api:us-east-1:495xxxxxxx:46xxxxxxx/dev/*/api/v1/*",
        },
      ],
    },
  };
  callback(null, ret);
}

Where the two * represent the method and the path (in my case after /api/v1).

chanan · October 2, 2020, 2:48pm

If anyone from serverless support read this - PLEASE update the docs to explain this…

chris · January 17, 2021, 2:02am

Thank you @chanan ! I had been running into this myself and it was quite mysterious.

rstar2 · October 16, 2021, 8:08pm

Thank you @chanan from me too, such a weird “bug”, I experienced the same and was going crazy.

The actual docs are here: Introducing custom authorizers in Amazon API Gateway | AWS Compute Blog

Because policies are cached for a configured TTL, API Gateway only invokes your Lambda function the first time it sees a token; all of the calls that follow during the TTL period are authorized by API Gateway using the cached policy.

Topic		Replies	Views
403 CloudFront for newly created items Serverless Framework aws	5	2090	October 24, 2017
Cloudfront Custom Distribution to route /api/* traffic to API Gateway ... Missing Authentication Token Error Serverless Framework aws , api-gateway	2	2222	May 27, 2020
Cloudfront with custom authorizer Serverless Framework aws , lambda	0	1764	April 30, 2018
Request type custom authorizer issue in serverless framework Serverless Framework aws , lambda , api-gateway	3	1218	June 27, 2022
Custom authorizer error not returned to client Serverless Framework	1	2294	October 14, 2019

HELP! Really weird access denied issue

Related topics