Connecting to Snowflake very slow in AWS Lambda

[sher04lock]

1. What version of NodeJS are you using (node --version and npm --version)?

Node: v14.21.2
NPM: 6.14.17
Node on lambda: nodejs14.x

2. What operating system and processor architecture are you using?

AWS Lambda runtime
Node 14.x
memory: 1024 MB
timeout: 15 min
region: us-east-1

3. What are the component versions in the environment (npm list)?

├── @serverless/typescript@3.25.0
├── @types/aws-lambda@8.10.109
├── @types/node@14.18.36
├── @types/snowflake-sdk@1.6.12
├── esbuild@0.14.54
├── json-schema-to-ts@1.6.5
├── serverless@3.26.0
├── serverless-esbuild@1.37.2
├── snowflake-sdk@1.6.17
├── ts-node@10.9.1
├── tsconfig-paths@3.14.1
└── typescript@4.9.4

4. What did you do?
   Bootstrapped new serverless project with typescript, added simple connection to snowflake and deployed it.

5. What did you expect to see?
   Connection made within milliseconds or seconds (excluding cold start time for lambda)

6. What did you see instead?
   Connection made in minutes.

Example logs:

2023-01-25T09:25:08.798Z INIT_START Runtime Version: nodejs:14.v28 Runtime Version ARN: arn:aws:lambda:us-east-1::runtime:be4a32da6aeaa90583d476cb548ced79ae2c9aa7b14a45129198bbd13ea5822d
2023-01-25T09:25:10.211Z START RequestId: a8524c84-ba27-40ab-a406-1f2d24c4ff3a Version: $LATEST
2023-01-25T09:25:10.334Z a8524c84-ba27-40ab-a406-1f2d24c4ff3a INFO >>>>> Connecting to SF...
{"level":"DEBUG","message":"[9:25:10.2510 AM]: Contacting SF: /session/v1/login-request?requestId=f06e73bc-88eb-47aa-bfe1-e26f10dabfdb&warehouse=XXXX&databaseName=DDD&roleName=XXXX, (1/5)"}`
{"level":"TRACE","message":"[9:25:10.2510 AM]: https://nc51688.us-east-2.aws.snowflakecomputing.com/session/v1/login-request?requestId=f06e73bc-88eb-47aa-bfe1-e26f10dabfdb&warehouse=XXXX&databaseName=DDD&roleName=XXXX"}
2023-01-25T09:25:10.398Z a8524c84-ba27-40ab-a406-1f2d24c4ff3a ERROR (node:8) [DEP0005] DeprecationWarning: Buffer() is deprecated due to security and usability issues. Please use the Buffer.alloc(), Buffer.allocUnsafe(), or Buffer.from() methods instead. (Use `node --trace-deprecation ...` to show where the warning was created)
{"level":"DEBUG","message":"[9:25:24.2524 AM]: Reading OCSP cache file. /home/sbx_user1051/.cache/snowflake/ocsp_response_cache.json"}
{"level":"DEBUG","message":"[9:25:25.2525 AM]: Failed to read OCSP cache file: /home/sbx_user1051/.cache/snowflake/ocsp_response_cache.json, err: Error: ENOENT: no such file or directory, open '/home/sbx_user1051/.cache/snowflake/ocsp_response_cache.json'\n    at Object.openSync (fs.js:498:3)\n    at Object.readFileSync (fs.js:394:35)\n    at OcspResponseCache.OcspResponseCache (/node_modules/snowflake-sdk/lib/agent/ocsp_response_cache.js:79:25)\n    at getOcspResponseCache (/node_modules/snowflake-sdk/lib/agent/socket_util.js:40:37)\n    at getO"}
{"level":"TRACE","message":"[9:25:53.2553 AM]: socket reused = false"}
{"level":"TRACE","message":"[9:25:54.2554 AM]: Contact OCSP Cache Server: http://ocsp.snowflakecomputing.com/ocsp_response_cache.json"}
{"level":"DEBUG","message":"[9:25:54.2554 AM]: Finish OCSP Cache Server: http://ocsp.snowflakecomputing.com/ocsp_response_cache.json"}
{"level":"TRACE","message":"[9:27:34.2734 AM]: Returning OCSP status for certificate 02F3C1F7262598E5C860EA4AF9308CA0 from cache"}
{"level":"TRACE","message":"[9:27:55.2755 AM]: Returning OCSP status for certificate 067F94578587E8AC77DEB253325BBC998B560D from cache"}
{"level":"TRACE","message":"[9:28:17.2817 AM]: Returning OCSP status for certificate 067F944A2A27CDF3FAC2AE2B01F908EEB9C4C6 from cache"}
{"level":"TRACE","message":"[9:28:31.2831 AM]: Returning OCSP status for certificate A70E4A4C3482B77F from cache"}
{"level":"DEBUG","message":"[9:28:33.2833 AM]: /home/sbx_user1051/.cache/snowflake/ocsp_response_cache.json"}
{"level":"DEBUG","message":"[9:28:33.2833 AM]: Writing OCSP cache file. /home/sbx_user1051/.cache/snowflake/ocsp_response_cache.json"}
{"level":"DEBUG","message":"[9:28:33.2833 AM]: Failed to update OCSP cache file: /home/sbx_user1051/.cache/snowflake/ocsp_response_cache.json, err: Error: ENOENT: no such file or directory, open '/home/sbx_user1051/.cache/snowflake/ocsp_response_cache.json'\n    at Object.openSync (fs.js:498:3)\n    at Object.writeFileSync (fs.js:1529:35)\n    at OcspResponseCache.OcspResponseCache.resetCacheStatus (/node_modules/snowflake-sdk/lib/agent/ocsp_response_cache.js:138:12)\n    at <anonymous> (/node_modules/snowflake-sdk/lib/agent/socket_util.js:90:32"}
{"level":"TRACE","message":"[9:28:33.2833 AM]: OCSP validation succeeded for nc51688.us-east-2.aws.snowflakecomputing.com"}
{"level":"DEBUG","message":"[9:28:34.2834 AM]: Contacting SF: /session/v1/login-request?requestId=83651885-b25d-423f-a7c4-428e2c5749c1&warehouse=XXXX&databaseName=DDD&roleName=XXXXXX, (2/5)"}
{"level":"TRACE","message":"[9:28:34.2834 AM]: https://nc51688.us-east-2.aws.snowflakecomputing.com/session/v1/login-request?requestId=83651885-b25d-423f-a7c4-428e2c5749c1&warehouse=XXXX&databaseName=DDD&roleName=XXXXXX"}
{"level":"TRACE","message":"[9:29:01.291 AM]: Returning OCSP status for certificate 02F3C1F7262598E5C860EA4AF9308CA0 from cache"}
{"level":"TRACE","message":"[9:29:23.2923 AM]: Returning OCSP status for certificate 067F94578587E8AC77DEB253325BBC998B560D from cache"}
{"level":"TRACE","message":"[9:29:46.2946 AM]: Returning OCSP status for certificate 067F944A2A27CDF3FAC2AE2B01F908EEB9C4C6 from cache"}
{"level":"TRACE","message":"[9:29:59.2959 AM]: Returning OCSP status for certificate A70E4A4C3482B77F from cache"}
{"level":"TRACE","message":"[9:30:01.301 AM]: socket reused = false"}
{"level":"TRACE","message":"[9:30:01.301 AM]: OCSP validation succeeded for nc51688.us-east-2.aws.snowflakecomputing.com"}
2023-01-25T09:30:01.546Z a8524c84-ba27-40ab-a406-1f2d24c4ff3a INFO >>>>> SF connected
2023-01-25T09:30:01.550Z END RequestId: a8524c84-ba27-40ab-a406-1f2d24c4ff3a
2023-01-25T09:30:01.550Z REPORT RequestId: a8524c84-ba27-40ab-a406-1f2d24c4ff3a Duration: 291334.88 ms Billed Duration: 291335 ms Memory Size: 1024 MB Max Memory Used: 503 MB Init Duration: 1412.29 ms

Does increasing memory helped?
A bit, but still very slow. With 2048 MB connection took 2 min 12s.

Repo with sample project to reproduce:
https://github.com/sher04lock/sftest

Please note the timestamps in above logs.
Duration of a function was 291334.88ms (4 min 48s), Init duration was only 1412.29ms (not event 1.5s)

This problem does not occur when invoking function locally (either via serverless, or directly JS file which was created by serverless package command).

[sfc-gh-dszmolka]

hi, thank you for raising the issue and major kudos for the self-contained reproduction. the issue can be reproduced at will, thanks to the instructions.
the issue seems to be that the OCSP validation is super slow, due to reasons which need to be uncovered. should be instantaneous; since the OCSP cache file (after downloaded from the remote OCSP Cache) is read into memory and all subsequent validation is only done in memory as far as i know.

i thought specifying envvar SF_OCSP_RESPONSE_CACHE_DIR=/tmp would help here, to point the OCSP cache download location to a place which is actually writable, but didn't help since the download itself seems to be working as expected, just the validation phase is slow (~20 seconds for a single entry; and depending on the cloud provider of the Snowflake account, this needs to be done 2-4 times per connection... makes it really slow in this case)

anyways. as an immediate relief, I found that configuring insecure mode with insecureConnect: true works, and connection is immediate since the whole OCSP checking is skipped. in your reproduction's case , this means putting

configure({ insecureConnect: true });

in src/functions/sftest/handler.ts

can you please try it and see if it helps improving the execution speed for you too ? in parallel, we're going to take a look why the OCSP validation is so super slow when code is deployed with serverless (i didn't see such issue when i invoked another Lambda function, which is based for example on a Docker image) . but this investigation will probably going to take some time.

[sfc-gh-dszmolka]

also discovered that even without configuring insecureConnect (so just leaving everything at its default), but leaving --enable-source-maps from NODE_OPTIONS again resulted in immediate execution times, now with OCSP checking.

so at this point i'm not entirely sure if the issue is with the connector. can you please try it, just excluding --enable-source-maps out from the options but leaving everything at its default, if it works for you too ?
(in this case, I recommend configuring envvar SF_OCSP_RESPONSE_CACHE_DIR=/tmp so the OCSP cache file is only downloaded once - to a writeable location)

[sher04lock]

Thanks for looking into it so quickly.

You are right, removing --enable-source-maps flag fixes the problem, connection is made in ~1s. Quick search about source and looks like it's not a problem related only to snowflake-connector, but source maps in general:

nodejs/node#41541
https://github.com/mjpowersjr/source-map-performance-demo

I was able to get similar good performance with --enable-source-maps when I moved snowflake-sdk to external array in esbuild:

external: ["snowflake-sdk"],

Although that increases bundle size from 3.7MB to 24MB. So you need to choose either better stack traces or smaller bundle size.

I think it's still worth investigating the OCSP validation when the source maps are enabled and code is bundled with esbuild - we didn't have this problem with any other library so far.

[sfc-gh-dszmolka]

yes indeed, maybe it's still worth digging into this a bit further. passed this to my colleagues to look into it with low priority, so i don't expect any quick updates on the root cause, but will update this Issue too once there's any news available back

[sfc-gh-dszmolka]

closing this Issue as there is a working solution to it, also doesn't seem to be directly coming from the Snowflake nodejs driver as you mentioned previously

looks like it's not a problem related only to snowflake-connector, but source maps in general:

nodejs/node#41541
https://github.com/mjpowersjr/source-map-performance-demo

we'll focus the resources on other, higher priority issues