Library @google-cloud/secret-manager does not work reliably

[bsansouci]

What version of Bun is running?

1.0.29

What platform is your computer?

Darwin 23.3.0 arm64 arm

What steps can reproduce the bug?

Unfortunately it's not trivial to repro because you'll need a GCP account, create a project called bun-repro, enable Secret Manager, add variable called MY_SECRET.
If anyone here gives me their email I can add them to a repro GCP project that is all setup so you can repro this easily

Then run this

import { SecretManagerServiceClient } from '@google-cloud/secret-manager';

async function stuff() {
  const client = new SecretManagerServiceClient()
  console.log("Starting")
  await client.accessSecretVersion({
    name: `projects/bun-repro/secrets/MY_SECRET/versions/latest`,
  })
  console.log("This should print")
}

stuff()

That will print "Starting" but never reach "This should print", or at least frequently it won't, every once in a while it does work.

What is the expected behavior?

It fetches and prints "This should print"

What do you see instead?

It won't print "This should print", it'll stall after "Starting". It also won't explicitly timeout as far as I can tell which is odd.

Additional information

Seems like in nodejs it's also super slow, sometimes up to 10s for some reason.
I skimmed the code for that module and they're using gRPC and protobuf, both of which seem likely to be the culprit.
This is where they create the abstract function that gets called when accessSecretVersion is called, which seems to just setup a grpc call basically.

[Jarred-Sumner]

debug logs:

[SYS] openat(-2, /Users/jarred/Build/fireystore/KEY_FILE.p12) = 4
[SYS] close(4[/Users/jarred/Build/fireystore/KEY_FILE.p12])
[SYS] openat(-2, /Users/jarred/Build/fireystore/KEY_FILE.p12) = 4
[alloc] new() = src.bun.js.webcore.streams.ReadableStreamSource(src.bun.js.webcore.streams.FileReader,"File",(function 'onStart'),(function 'onPull'),(function 'onCancel'),(function 'deinit'),(function 'setRefOrUnref'),(function 'drain'))@13fc04170
[SYS] dup(4) = 9
[SYS] fstat(9[/Users/jarred/Build/fireystore/KEY_FILE.p12]) = 0
[SYS] read(9[/Users/jarred/Build/fireystore/KEY_FILE.p12], 262144) = 2362 (0.012ms)
[SYS] read(9[/Users/jarred/Build/fireystore/KEY_FILE.p12], 259782) = 0 (0.002ms)
[alloc] new() = posix_event_loop.Closer@13fd04090
[SYS] close(9[/Users/jarred/Build/fireystore/KEY_FILE.p12])
[alloc] destroy(posix_event_loop.Closer@13fd04090)
[FileReader] onReadChunk() = 2362 (eof)
[FileReader] onReaderDone()
[FileReader] onPull(65536) = 2362
[Loop] ref
[Loop] sub 1 - 1 = 0
[Loop] ref
[Loop] sub 1 - 1 = 0
[Loop] ref
[Loop] sub 1 - 1 = 0
[Loop] ref
[Loop] sub 1 - 1 = 0
[Loop] ref
[Loop] sub 1 - 1 = 0
[Loop] ref
[Loop] ref
[Loop] sub 2 - 1 = 1
[Loop] ref
[Loop] sub 2 - 1 = 1
[GetAddrInfoRequest] init
[Loop] ref
[SYS] FilePoll.initWithOwner(0x20000760010, generation_number=1, fd=2147483646)
[SYS] register: FilePoll(0x20000760010, generation_number=1) machport (15875)
[Loop] ref
[SYS] FilePoll.initWithOwner(0x20000760038, generation_number=2, fd=10)
[SYS] register: FilePoll(0x20000760038, generation_number=2) readable (10)
[Loop] ref
[Loop] sub 4 - 1 = 3
[Loop] ref
[EventLoop] tick 19.583us
[SYS] onKqueueEvent(0x20000760038, generation_number=2, ext=2, fd=10)
[SYS] onKQueueEvent: FilePoll(fd=10, generation_number=2) = poll_readable | readable | has_incremented_poll_count | was_ever_registered
[SYS] onUpdate kevent (fd: 10) DNSResolver
[EventLoop] enter() = 0
[Loop] sub 4 - 1 = 3
[SYS] unregister: FilePoll(0x20000760038, generation_number=2) readable (10)
[Loop] sub 3 - 0 = 3
[EventLoop] exit() = 0
[SYS] onKqueueEvent(0x20000760010, generation_number=1, ext=1, fd=2147483646)
[SYS] machport
[SYS] onKQueueEvent: FilePoll(fd=2147483646, generation_number=1) = poll_machport | machport | one_shot | has_incremented_poll_count | was_ever_registered
[SYS] onUpdate kevent (fd: 2147483646) GetAddrInfoRequest
[GetAddrInfoRequest] getAddrInfoAsyncCallback: status=0
[SYS] unregister: machport (2147483646) skipped due to needs_rearm
[Loop] sub 3 - 0 = 3
[DNSResolver] drainPendingHostNative
[DNSLookup] onCompleteWithArray
[DNSLookup] deinit
[Loop] sub 3 - 1 = 2
[Loop] ref
[Loop] sub 3 - 1 = 2
[Loop] ref
[Loop] sub 3 - 1 = 2
[Loop] ref
[Loop] sub 3 - 1 = 2
[Loop] ref
[Loop] sub 3 - 1 = 2
[Loop] ref
[Loop] sub 3 - 1 = 2
[Loop] ref
[Loop] sub 3 - 1 = 2
[Loop] ref
[Loop] sub 3 - 1 = 2
[Loop] ref
[Loop] sub 3 - 1 = 2
[Loop] ref
[Loop] sub 3 - 1 = 2
[Loop] ref
[Loop] sub 3 - 1 = 2
[Loop] ref
[Loop] sub 3 - 1 = 2
[Loop] ref
[Loop] sub 3 - 1 = 2
[Loop] ref
[Loop] sub 3 - 1 = 2
[Loop] ref
[Loop] sub 3 - 1 = 2
[Loop] ref
[Loop] sub 3 - 1 = 2
[Loop] ref
[Loop] sub 3 - 1 = 2
[Loop] ref
[Loop] sub 3 - 1 = 2
[Loop] ref
[Loop] sub 3 - 1 = 2
[Loop] ref
[Loop] sub 3 - 1 = 2
[Loop] ref
[Loop] sub 3 - 1 = 2
[Loop] ref
[Loop] sub 3 - 1 = 2
[Loop] ref
[Loop] sub 3 - 1 = 2
[Loop] ref
[Loop] sub 3 - 1 = 2
[uws] connect(142.250.189.202, 443)
[Loop] ref
[H2FrameParser] write
[EventLoop] enter() = 1
[EventLoop] exit() = 1
[Socket] onOpen ssl: true
[Listener] markActive
[EventLoop] enter() = 0
[Loop] sub 3 - 1 = 2
[EventLoop] exit() = 0
[Socket] onHandshake(1)
[Listener] markActive
[EventLoop] enter() = 0
[uws] us_socket_write(src.deps.boringssl.translated.SSL@600002475978, 69) = 69
[Socket] write(69, false) = 69
[Listener] markInactive
[EventLoop] exit() = 0
[H2FrameParser] single header :authority
[H2FrameParser] encode header :authority secretmanager.googleapis.com:443
[H2FrameParser] single header :method
[H2FrameParser] encode header :method POST
[H2FrameParser] single header :path
[H2FrameParser] encode header :path /google.cloud.secretmanager.v1.SecretManagerService/AccessSecretVersion
[H2FrameParser] single header :scheme
[H2FrameParser] encode header :scheme https
[H2FrameParser] array header x-goog-api-client
[H2FrameParser] encode header x-goog-api-client gax/4.3.1 gapic/5.1.0 gl-node/21.6.0 grpc/1.10.1
[H2FrameParser] array header x-goog-request-params
[H2FrameParser] encode header x-goog-request-params name=projects%2Fbionic-spot-410604%2Fsecrets%2FMY_SECRET%2Fversions%2Flatest
[H2FrameParser] array header grpc-accept-encoding
[H2FrameParser] encode header grpc-accept-encoding identity,deflate,gzip
[H2FrameParser] array header accept-encoding
[H2FrameParser] encode header accept-encoding identity
[H2FrameParser] array header authorization
[H2FrameParser] encode header authorization Bearer [redacted]
[H2FrameParser] array header grpc-timeout
[H2FrameParser] encode header grpc-timeout 59669m
[H2FrameParser] single header user-agent
[H2FrameParser] encode header user-agent grpc-node-js/1.10.1
[H2FrameParser] single header content-type
[H2FrameParser] encode header content-type application/grpc
[H2FrameParser] single header te
[H2FrameParser] encode header te trailers
[EventLoop] enter() = 1
[EventLoop] exit() = 1
[H2FrameParser] request encoded_size 882
[Loop] ref
[H2FrameParser] sendData(1, 68, false)
[H2FrameParser] sendData(1, 0, true)
[Socket] onWritable
[EventLoop] enter() = 0
[EventLoop] exit() = 0
[Socket] onData(49)
[Listener] markActive
[EventLoop] enter() = 0
[H2FrameParser] read
[H2FrameParser] new frame 4 18 0 0
[EventLoop] enter() = 1
[EventLoop] exit() = 1
[H2FrameParser] read
[H2FrameParser] new frame 8 4 0 0
[H2FrameParser] sendWindowUpdate stream 0 size 491520
[H2FrameParser] write
[EventLoop] enter() = 1
[uws] us_socket_write(src.deps.boringssl.translated.SSL@600002475978, 13) = 13
[Socket] write(13, false) = 13
[EventLoop] exit() = 1
[H2FrameParser] windowSizeIncrement stream 0 value 491520
[H2FrameParser] read
[H2FrameParser] new frame 4 0 1 0
[H2FrameParser] settings frame ACK
[H2FrameParser] write
[EventLoop] enter() = 1
[uws] us_socket_write(src.deps.boringssl.translated.SSL@600002475978, 977) = 977
[Socket] write(977, false) = 977
[EventLoop] exit() = 1
[EventLoop] enter() = 1
[EventLoop] exit() = 1
[Listener] markInactive
[EventLoop] exit() = 0
[Socket] onData(340)
[Listener] markActive
[EventLoop] enter() = 0
[H2FrameParser] read
[H2FrameParser] new frame 1 126 4 1
[H2FrameParser] decodeHeaderBlock
[H2FrameParser] header :status 200
[H2FrameParser] header content-type application/grpc
[H2FrameParser] header grpc-accept-encoding identity, deflate, gzip
[H2FrameParser] header content-disposition attachment
[H2FrameParser] header date Wed, 28 Feb 2024 09:17:37 GMT
[H2FrameParser] header alt-svc h3=":443"; ma=2592000,h3-29=":443"; ma=2592000
[EventLoop] enter() = 1
[EventLoop] exit() = 1
[H2FrameParser] read
[H2FrameParser] new frame 0 78 0 1
[EventLoop] enter() = 1
[EventLoop] exit() = 1
[H2FrameParser] read
[H2FrameParser] new frame 1 92 5 1
[H2FrameParser] decodeHeaderBlock
[H2FrameParser] header grpc-status 0
[H2FrameParser] header endpoint-load-metrics-bin MWyuIdsVUVJAOVmzvFo3WzhASXUrieRBDcg/
[H2FrameParser] header grpc-server-stats-bin AAAHzj0GAAAAAA
[EventLoop] enter() = 1
[EventLoop] exit() = 1
[EventLoop] enter() = 1
[EventLoop] exit() = 1
[H2FrameParser] read
[H2FrameParser] new frame 6 8 0 0
[H2FrameParser] write
[EventLoop] enter() = 1
[uws] us_socket_write(src.deps.boringssl.translated.SSL@600002475978, 17) = 17
[Socket] write(17, false) = 17
[EventLoop] exit() = 1
[EventLoop] enter() = 1
[EventLoop] exit() = 1
[Listener] markInactive
[EventLoop] exit() = 0
[Loop] sub 3 - 1 = 2
[Loop] sub 2 - 1 = 1
[Loop] ref
[Loop] sub 2 - 1 = 1
This should print

never exits after "This should print". I have not yet been able to get it to hang without printing "This should print", but maybe that's because the secret I am using is about 20 bytes

[Jarred-Sumner]

@cirospaciari do you have any ideas?

[bsansouci]

interesting, how can I help debug this? Can I run with this kind of verbose logs on my machine?

[cirospaciari]

@cirospaciari do you have any ideas?

Will take a look at the logs don't show that we exchange settings, windows update, request passing headers and body, received the response and trailers headers all successfully, will try with a bigger secret and see the logs again.

[cirospaciari]

Cant reproduce it after #14286 please reopen with a repro if is still happening