search

cloudflare / workers-sdk

⛅️ Home to Wrangler, the CLI for Cloudflare Workers®
https://developers.cloudflare.com/workers/
Apache License 2.0
2.57k stars 660 forks source link

🐛 BUG: Wrangler dev reporting logged out, fixed by `npx wrangler whoami` #2978

Open poacher2k opened 1 year ago

poacher2k commented 1 year ago

Which Cloudflare product(s) does this pertain to?

Wrangler

What version of Wrangler are you using?

2.13.0

What operating system are you using?

Mac

Describe the Bug

When it's been a while (~1 hr ? a day ?) since I've run wrangler dev, it fails with the following error: image

If I then run npx wrangler whoami, it correctly gets user settings and shows that I'm logged in. Subsequently, running wrangler dev again now succeeds.

penalosa commented 1 year ago

This is very odd, and definitely not expected behaviour—thanks for raising this! Can you reproduce this in multiple projects, or is it specific to a single one?

poacher2k commented 1 year ago

Can you reproduce this in multiple projects, or is it specific to a single one?

I'm running 2 workers at the same time, and I'm not sure if it's specific to both of them or if it's just that one of them is consistently failing first. I'll try waiting a while and running the other one to see if it's specific to the one worker.

petebacondarwin commented 1 year ago

So you are running them using some kind of parallelisation script? I think this means that they are in non-interactive mode, which is why it is not asking you to login.

When you just run either of the Workers does independently does it work oK?

Do you have any environment variables set like CLOUDFLARE_API_TOKEN, CF_API_TOKEN, CLOUDFLARE_API_KEY or CF_API_KEY?

Do you have a global auth config file? E.g. ~/.wrangler/config/default.toml or similar in your XDG App path?

poacher2k commented 1 year ago

So you are running them using some kind of parallelisation script? I think this means that they are in non-interactive mode, which is why it is not asking you to login.

Yes, I'm using turbo. It fails the first time (usually at the beginning of the day), and then works on consecutive runs after running eg. npx wrangler whoami or npx wrangler login.

When you just run either of the Workers does independently does it work oK?

I'll try when some time has passed.

Do you have any environment variables set like CLOUDFLARE_API_TOKEN, CF_API_TOKEN, CLOUDFLARE_API_KEY or CF_API_KEY?

Yes, I set CLOUDFLARE_TOKEN - can this be messing things up? It does, as mentioned, work on consecutive runs though 🤔

Do you have a global auth config file? E.g. ~/.wrangler/config/default.toml or similar in your XDG App path?

Yes, ~/.wrangler/config/default.toml exists.

petebacondarwin commented 1 year ago

Hmm. So each wrangler dev command should be picking up the CLOUDFLARE_API_TOKEN variable and using that first. Are you sure it is valid?

I was wonder if, maybe, the first time you run, it uses the CLOUDFLARE_API_TOKEN and fails. Then when you do a normal login, it is caching the correct API token in the global auth config file?

Can you try running with verbose debugging on to see if that helps provide more info? WRANGLER_LOG=debug npx wrangler dev? I.e. set this environment variable.

poacher2k commented 1 year ago

Hmm. So each wrangler dev command should be picking up the CLOUDFLARE_API_TOKEN variable and using that first. Are you sure it is valid?

Sorry, I realize I wasn't clear - I set CLOUDFLARE_TOKEN for use in my non-worker application. I rely on wrangler login for actually running the workers with needed permissions. I don't set CLOUDFLARE_API_TOKEN manually anywhere.

I was wonder if, maybe, the first time you run, it uses the CLOUDFLARE_API_TOKEN and fails. Then when you do a normal login, it is caching the correct API token in the global auth config file?

Makes sense, but shouldn't it pick up the global auth config file during the first run too?

Can you try running with verbose debugging on to see if that helps provide more info? WRANGLER_LOG=debug npx wrangler dev? I.e. set this environment variable.

Will do!

penalosa commented 1 year ago

@poacher2k Just quickly following up—did you have a chance to run this with verbose logging?

poacher2k commented 1 year ago

@poacher2k Just quickly following up—did you have a chance to run this with verbose logging?

I ran this just now. The following is the console logs for two consecutive runs of the exact same command, the 2nd done right after the 1st failed:

1st run 
➜  instorier ✗ npm run dev:local

> instorier@0.0.0 dev:local
> npm run dev-env -- turbo run dev --parallel --filter=@instorier/service --filter=@instorier/worker-files-proxy --filter=@instorier/worker-stories-handler

> instorier@0.0.0 dev-env
> npm run docker && dotenv -e .env.local -- turbo run dev --parallel --filter=@instorier/service --filter=@instorier/worker-files-proxy --filter=@instorier/worker-stories-handler

> instorier@0.0.0 docker
> docker-compose up -d && echo "MailPit running at http://localhost:8025"

[+] Running 2/0
 ⠿ Container instorier_redis    Running                                                                                                                                                                                                0.0s
 ⠿ Container instorier_mailpit  Running                                                                                                                                                                                                0.0s
MailPit running at http://localhost:8025
• Packages in scope: @instorier/service, @instorier/worker-files-proxy, @instorier/worker-stories-handler
• Running dev in 3 packages
• Remote caching enabled
@instorier/worker-files-proxy:dev: cache bypass, force executing 9c404fd3c45744e2
@instorier/worker-stories-handler:dev: cache bypass, force executing b5f22e2000a8f70e
@instorier/worker-stories-handler:dev: 
@instorier/worker-stories-handler:dev: > @instorier/worker-stories-handler@1.0.0 dev
@instorier/worker-stories-handler:dev: > wrangler dev --env dev --port 8789 --inspector-port 9229
@instorier/worker-stories-handler:dev: 
@instorier/worker-files-proxy:dev: 
@instorier/worker-files-proxy:dev: > @instorier/worker-files-proxy@1.0.0 dev
@instorier/worker-files-proxy:dev: > wrangler dev --port 8790 --inspector-port 9230
@instorier/worker-files-proxy:dev: 
@instorier/worker-files-proxy:dev: Failed to load .env file ".env": Error: ENOENT: no such file or directory, open '.env'
@instorier/worker-files-proxy:dev:     at Object.openSync (node:fs:600:3)
@instorier/worker-files-proxy:dev:     at Object.readFileSync (node:fs:468:35)
@instorier/worker-files-proxy:dev:     at tryLoadDotEnv (/Users/poacher2k/development/instorier/instorier/node_modules/wrangler/wrangler-dist/cli.js:126038:72)
@instorier/worker-files-proxy:dev:     at loadDotEnv (/Users/poacher2k/development/instorier/instorier/node_modules/wrangler/wrangler-dist/cli.js:126047:12)
@instorier/worker-files-proxy:dev:     at /Users/poacher2k/development/instorier/instorier/node_modules/wrangler/wrangler-dist/cli.js:148455:20
@instorier/worker-files-proxy:dev:     at /Users/poacher2k/development/instorier/instorier/node_modules/wrangler/wrangler-dist/cli.js:134845:16
@instorier/worker-files-proxy:dev:     at maybeAsyncResult (/Users/poacher2k/development/instorier/instorier/node_modules/wrangler/wrangler-dist/cli.js:133092:44)
@instorier/worker-files-proxy:dev:     at /Users/poacher2k/development/instorier/instorier/node_modules/wrangler/wrangler-dist/cli.js:134844:14
@instorier/worker-files-proxy:dev:     at /Users/poacher2k/development/instorier/instorier/node_modules/wrangler/wrangler-dist/cli.js:133079:22
@instorier/worker-files-proxy:dev:     at Array.reduce () {
@instorier/worker-files-proxy:dev:   errno: -2,
@instorier/worker-files-proxy:dev:   syscall: 'open',
@instorier/worker-files-proxy:dev:   code: 'ENOENT',
@instorier/worker-files-proxy:dev:   path: '.env'
@instorier/worker-files-proxy:dev: }
@instorier/worker-stories-handler:dev: Failed to load .env file ".env.dev": Error: ENOENT: no such file or directory, open '.env.dev'
@instorier/worker-stories-handler:dev:     at Object.openSync (node:fs:600:3)
@instorier/worker-stories-handler:dev:     at Object.readFileSync (node:fs:468:35)
@instorier/worker-stories-handler:dev:     at tryLoadDotEnv (/Users/poacher2k/development/instorier/instorier/node_modules/wrangler/wrangler-dist/cli.js:126038:72)
@instorier/worker-stories-handler:dev:     at loadDotEnv (/Users/poacher2k/development/instorier/instorier/node_modules/wrangler/wrangler-dist/cli.js:126049:12)
@instorier/worker-stories-handler:dev:     at /Users/poacher2k/development/instorier/instorier/node_modules/wrangler/wrangler-dist/cli.js:148455:20
@instorier/worker-stories-handler:dev:     at /Users/poacher2k/development/instorier/instorier/node_modules/wrangler/wrangler-dist/cli.js:134845:16
@instorier/worker-stories-handler:dev:     at maybeAsyncResult (/Users/poacher2k/development/instorier/instorier/node_modules/wrangler/wrangler-dist/cli.js:133092:44)
@instorier/worker-stories-handler:dev:     at /Users/poacher2k/development/instorier/instorier/node_modules/wrangler/wrangler-dist/cli.js:134844:14
@instorier/worker-stories-handler:dev:     at /Users/poacher2k/development/instorier/instorier/node_modules/wrangler/wrangler-dist/cli.js:133079:22
@instorier/worker-stories-handler:dev:     at Array.reduce () {
@instorier/worker-stories-handler:dev:   errno: -2,
@instorier/worker-stories-handler:dev:   syscall: 'open',
@instorier/worker-stories-handler:dev:   code: 'ENOENT',
@instorier/worker-stories-handler:dev:   path: '.env.dev'
@instorier/worker-stories-handler:dev: }
@instorier/worker-stories-handler:dev: Failed to load .env file ".env": Error: ENOENT: no such file or directory, open '.env'
@instorier/worker-stories-handler:dev:     at Object.openSync (node:fs:600:3)
@instorier/worker-stories-handler:dev:     at Object.readFileSync (node:fs:468:35)
@instorier/worker-stories-handler:dev:     at tryLoadDotEnv (/Users/poacher2k/development/instorier/instorier/node_modules/wrangler/wrangler-dist/cli.js:126038:72)
@instorier/worker-stories-handler:dev:     at loadDotEnv (/Users/poacher2k/development/instorier/instorier/node_modules/wrangler/wrangler-dist/cli.js:126049:50)
@instorier/worker-stories-handler:dev:     at /Users/poacher2k/development/instorier/instorier/node_modules/wrangler/wrangler-dist/cli.js:148455:20
@instorier/worker-stories-handler:dev:     at /Users/poacher2k/development/instorier/instorier/node_modules/wrangler/wrangler-dist/cli.js:134845:16
@instorier/worker-stories-handler:dev:     at maybeAsyncResult (/Users/poacher2k/development/instorier/instorier/node_modules/wrangler/wrangler-dist/cli.js:133092:44)
@instorier/worker-stories-handler:dev:     at /Users/poacher2k/development/instorier/instorier/node_modules/wrangler/wrangler-dist/cli.js:134844:14
@instorier/worker-stories-handler:dev:     at /Users/poacher2k/development/instorier/instorier/node_modules/wrangler/wrangler-dist/cli.js:133079:22
@instorier/worker-stories-handler:dev:     at Array.reduce () {
@instorier/worker-stories-handler:dev:   errno: -2,
@instorier/worker-stories-handler:dev:   syscall: 'open',
@instorier/worker-stories-handler:dev:   code: 'ENOENT',
@instorier/worker-stories-handler:dev:   path: '.env'
@instorier/worker-stories-handler:dev: }
@instorier/worker-files-proxy:dev: Checking if domain has Access enabled: dash.cloudflare.com
@instorier/worker-files-proxy:dev: Access switch not cached for: dash.cloudflare.com
@instorier/worker-stories-handler:dev: Checking if domain has Access enabled: dash.cloudflare.com
@instorier/worker-stories-handler:dev: Access switch not cached for: dash.cloudflare.com
@instorier/worker-stories-handler:dev: Caching access switch for: dash.cloudflare.com
@instorier/worker-files-proxy:dev: Caching access switch for: dash.cloudflare.com
@instorier/worker-files-proxy:dev: 
@instorier/worker-files-proxy:dev: ✘ [ERROR] You must be logged in to use wrangler dev in remote mode. Try logging in, or run wrangler dev --local.
@instorier/worker-files-proxy:dev: 
@instorier/worker-files-proxy:dev: 
@instorier/worker-files-proxy:dev: If you think this is a bug then please create an issue at https://github.com/cloudflare/workers-sdk/issues/new/choose
@instorier/worker-files-proxy:dev: npm ERR! Lifecycle script `dev` failed with error: 
@instorier/worker-files-proxy:dev: npm ERR! Error: command failed 
@instorier/worker-files-proxy:dev: npm ERR!   in workspace: @instorier/worker-files-proxy@1.0.0 
@instorier/worker-files-proxy:dev: npm ERR!   at location: /Users/poacher2k/development/instorier/instorier/apps/worker-files-proxy 
@instorier/worker-files-proxy:dev: ERROR: command finished with error: command (/Users/poacher2k/development/instorier/instorier/apps/worker-files-proxy) npm run dev exited (1)
command (/Users/poacher2k/development/instorier/instorier/apps/worker-files-proxy) npm run dev exited (1)

 Tasks:    0 successful, 4 total
Cached:    0 cached, 4 total
  Time:    5.603s 

 ERROR  run failed: command  exited (1)
2nd run 
➜  instorier ✗ npm run dev:local

> instorier@0.0.0 dev:local
> npm run dev-env -- turbo run dev --parallel --filter=@instorier/service --filter=@instorier/worker-files-proxy --filter=@instorier/worker-stories-handler

> instorier@0.0.0 dev-env
> npm run docker && dotenv -e .env.local -- turbo run dev --parallel --filter=@instorier/service --filter=@instorier/worker-files-proxy --filter=@instorier/worker-stories-handler

> instorier@0.0.0 docker
> docker-compose up -d && echo "MailPit running at http://localhost:8025"

[+] Running 2/0
 ⠿ Container instorier_redis    Running                                                                                                                                                                                                0.0s
 ⠿ Container instorier_mailpit  Running                                                                                                                                                                                                0.0s
MailPit running at http://localhost:8025
• Packages in scope: @instorier/service, @instorier/worker-files-proxy, @instorier/worker-stories-handler
• Running dev in 3 packages
• Remote caching enabled
@instorier/worker-stories-handler:dev: cache bypass, force executing b5f22e2000a8f70e
@instorier/worker-files-proxy:dev: cache bypass, force executing 9c404fd3c45744e2
@instorier/worker-files-proxy:dev: 
@instorier/worker-files-proxy:dev: > @instorier/worker-files-proxy@1.0.0 dev
@instorier/worker-files-proxy:dev: > wrangler dev --port 8790 --inspector-port 9230
@instorier/worker-files-proxy:dev: 
@instorier/worker-stories-handler:dev: 
@instorier/worker-stories-handler:dev: > @instorier/worker-stories-handler@1.0.0 dev
@instorier/worker-stories-handler:dev: > wrangler dev --env dev --port 8789 --inspector-port 9229
@instorier/worker-stories-handler:dev: 
@instorier/worker-files-proxy:dev: Failed to load .env file ".env": Error: ENOENT: no such file or directory, open '.env'
@instorier/worker-files-proxy:dev:     at Object.openSync (node:fs:600:3)
@instorier/worker-files-proxy:dev:     at Object.readFileSync (node:fs:468:35)
@instorier/worker-files-proxy:dev:     at tryLoadDotEnv (/Users/poacher2k/development/instorier/instorier/node_modules/wrangler/wrangler-dist/cli.js:126038:72)
@instorier/worker-files-proxy:dev:     at loadDotEnv (/Users/poacher2k/development/instorier/instorier/node_modules/wrangler/wrangler-dist/cli.js:126047:12)
@instorier/worker-files-proxy:dev:     at /Users/poacher2k/development/instorier/instorier/node_modules/wrangler/wrangler-dist/cli.js:148455:20
@instorier/worker-files-proxy:dev:     at /Users/poacher2k/development/instorier/instorier/node_modules/wrangler/wrangler-dist/cli.js:134845:16
@instorier/worker-files-proxy:dev:     at maybeAsyncResult (/Users/poacher2k/development/instorier/instorier/node_modules/wrangler/wrangler-dist/cli.js:133092:44)
@instorier/worker-files-proxy:dev:     at /Users/poacher2k/development/instorier/instorier/node_modules/wrangler/wrangler-dist/cli.js:134844:14
@instorier/worker-files-proxy:dev:     at /Users/poacher2k/development/instorier/instorier/node_modules/wrangler/wrangler-dist/cli.js:133079:22
@instorier/worker-files-proxy:dev:     at Array.reduce () {
@instorier/worker-files-proxy:dev:   errno: -2,
@instorier/worker-files-proxy:dev:   syscall: 'open',
@instorier/worker-files-proxy:dev:   code: 'ENOENT',
@instorier/worker-files-proxy:dev:   path: '.env'
@instorier/worker-files-proxy:dev: }
@instorier/worker-stories-handler:dev: Failed to load .env file ".env.dev": Error: ENOENT: no such file or directory, open '.env.dev'
@instorier/worker-stories-handler:dev:     at Object.openSync (node:fs:600:3)
@instorier/worker-stories-handler:dev:     at Object.readFileSync (node:fs:468:35)
@instorier/worker-stories-handler:dev:     at tryLoadDotEnv (/Users/poacher2k/development/instorier/instorier/node_modules/wrangler/wrangler-dist/cli.js:126038:72)
@instorier/worker-stories-handler:dev:     at loadDotEnv (/Users/poacher2k/development/instorier/instorier/node_modules/wrangler/wrangler-dist/cli.js:126049:12)
@instorier/worker-stories-handler:dev:     at /Users/poacher2k/development/instorier/instorier/node_modules/wrangler/wrangler-dist/cli.js:148455:20
@instorier/worker-stories-handler:dev:     at /Users/poacher2k/development/instorier/instorier/node_modules/wrangler/wrangler-dist/cli.js:134845:16
@instorier/worker-stories-handler:dev:     at maybeAsyncResult (/Users/poacher2k/development/instorier/instorier/node_modules/wrangler/wrangler-dist/cli.js:133092:44)
@instorier/worker-stories-handler:dev:     at /Users/poacher2k/development/instorier/instorier/node_modules/wrangler/wrangler-dist/cli.js:134844:14
@instorier/worker-stories-handler:dev:     at /Users/poacher2k/development/instorier/instorier/node_modules/wrangler/wrangler-dist/cli.js:133079:22
@instorier/worker-stories-handler:dev:     at Array.reduce () {
@instorier/worker-stories-handler:dev:   errno: -2,
@instorier/worker-stories-handler:dev:   syscall: 'open',
@instorier/worker-stories-handler:dev:   code: 'ENOENT',
@instorier/worker-stories-handler:dev:   path: '.env.dev'
@instorier/worker-stories-handler:dev: }
@instorier/worker-stories-handler:dev: Failed to load .env file ".env": Error: ENOENT: no such file or directory, open '.env'
@instorier/worker-stories-handler:dev:     at Object.openSync (node:fs:600:3)
@instorier/worker-stories-handler:dev:     at Object.readFileSync (node:fs:468:35)
@instorier/worker-stories-handler:dev:     at tryLoadDotEnv (/Users/poacher2k/development/instorier/instorier/node_modules/wrangler/wrangler-dist/cli.js:126038:72)
@instorier/worker-stories-handler:dev:     at loadDotEnv (/Users/poacher2k/development/instorier/instorier/node_modules/wrangler/wrangler-dist/cli.js:126049:50)
@instorier/worker-stories-handler:dev:     at /Users/poacher2k/development/instorier/instorier/node_modules/wrangler/wrangler-dist/cli.js:148455:20
@instorier/worker-stories-handler:dev:     at /Users/poacher2k/development/instorier/instorier/node_modules/wrangler/wrangler-dist/cli.js:134845:16
@instorier/worker-stories-handler:dev:     at maybeAsyncResult (/Users/poacher2k/development/instorier/instorier/node_modules/wrangler/wrangler-dist/cli.js:133092:44)
@instorier/worker-stories-handler:dev:     at /Users/poacher2k/development/instorier/instorier/node_modules/wrangler/wrangler-dist/cli.js:134844:14
@instorier/worker-stories-handler:dev:     at /Users/poacher2k/development/instorier/instorier/node_modules/wrangler/wrangler-dist/cli.js:133079:22
@instorier/worker-stories-handler:dev:     at Array.reduce () {
@instorier/worker-stories-handler:dev:   errno: -2,
@instorier/worker-stories-handler:dev:   syscall: 'open',
@instorier/worker-stories-handler:dev:   code: 'ENOENT',
@instorier/worker-stories-handler:dev:   path: '.env'
@instorier/worker-stories-handler:dev: }
@instorier/worker-stories-handler:dev:  ⛅️ wrangler 2.13.0 (update available 2.15.1)
@instorier/worker-stories-handler:dev: ---------------------------------------------
@instorier/worker-files-proxy:dev:  ⛅️ wrangler 2.13.0 (update available 2.15.1)
@instorier/worker-files-proxy:dev: ---------------------------------------------
@instorier/worker-stories-handler:dev: Your worker has access to the following bindings:
@instorier/worker-stories-handler:dev: - KV Namespaces:
@instorier/worker-stories-handler:dev:   - REDACTED: REDACTED
@instorier/worker-stories-handler:dev: - R2 Buckets:
@instorier/worker-stories-handler:dev:   - REDACTED: REDACTED
@instorier/worker-stories-handler:dev: - Vars:
@instorier/worker-stories-handler:dev:   - REDACTED: "REDACTED"
@instorier/worker-stories-handler:dev:   - REDACTED: "REDACTED"
@instorier/worker-stories-handler:dev:   - REDACTED: "REDACTED"
@instorier/worker-stories-handler:dev:   - REDACTED: "REDACTED"
@instorier/worker-files-proxy:dev: Your worker has access to the following bindings:
@instorier/worker-files-proxy:dev: - R2 Buckets:
@instorier/worker-files-proxy:dev:   - REDACTED: REDACTED
@instorier/worker-stories-handler:dev: ⬣ Listening at http://0.0.0.0:8789
- http://127.0.0.1:8789
- http://192.168.1.6:8789
@instorier/worker-stories-handler:dev: 
@instorier/worker-files-proxy:dev: ⬣ Listening at http://0.0.0.0:8790
- http://127.0.0.1:8790
- http://192.168.1.6:8790
@instorier/worker-files-proxy:dev: 
Total Upload: 9.33 KiB / gzip: 2.81 KiB
Total Upload: 20.42 KiB / gzip: 4.59 KiB
@instorier/worker-stories-handler:dev:
poacher2k commented 1 year ago

@penalosa : Just a quick follow-up to say this still occurs with ^3.1.1

mrbbot commented 1 year ago

Hey! 👋 Apologies for the delayed response here. I'm unable to see what's going wrong here from the verbose logging. Any chance you could put together a minimal reproduction/share your code here?

poacher2k commented 1 year ago

Hey! 👋 Apologies for the delayed response here. I'm unable to see what's going wrong here from the verbose logging. Any chance you could put together a minimal reproduction/share your code here?

Heyo! No worries :) Here you go: https://github.com/poacher2k/workers-sdk-issue-2978-repro

penalosa commented 4 months ago

Having investigated this a bit, this is due to a race condition with both Wrangler processes trying to use the same Oauth refresh token at the same time.

As a workaround, you can run npx wrangler whoami, which will refresh your auth tokens.

poacher2k commented 3 months ago

As a workaround, you can run npx wrangler whoami, which will refresh your auth tokens.

Sadly this (and even just the default behavior now) makes it extra annoying, as it now automatically opens a browser tab asking me if I want to give Wrangler access etc. Before it would just fail and I could re-run it immediately - now I have to close the browser tab, and manually exit the processes before I can re-run it.

poacher2k commented 2 months ago

To anyone else experiencing this, I've managed to work around it by adding sleep N, eg. sleep 3 && wrangler dev to my workers, incrementing N by a couple for each of them to have them start sequentially instead of in parallel - works like a charm!