[Bug]: "Load error: Resource recorder error" when waking from idle
OmmyZhang opened this issue · 5 comments
OmmyZhang commented
What happened?
The deployment command works well, but when it waked from idle, it always crashed because of "Resource recorder error". Sometimes "could not verify project ownership" and sometimes ""This resource endpoint is discontinued. Please restart your project."
Version
v0.39.0
Which operating system(s) are you seeing the problem on?
In deployment
Which CPU architectures are you seeing the problem on?
In deployment
Relevant log output
2024-02-24T07:42:19.471932Z [Deployer] INFO start_deployment
2024-02-24T07:42:19.472074Z [Deployer] INFO Entering Built state
2024-02-24T07:42:19.472076Z [Deployer] INFO Starting deployment
2024-02-24T07:42:19.472219Z [Deployer] INFO Entering Loading state
2024-02-24T07:42:19.472222Z [Deployer] INFO Loading resources
2024-02-24T07:42:19.472288Z [Deployer] INFO shuttle_service::runner: {args="/opt/shuttle/shuttle-builds/remove-box-rs/.shuttle-executables/28ac3c9e-cde5-413e-862c-2ac127b1edbb --port 20004 --provisioner-address http://provisioner:8000/ --env production --auth-uri http://auth:8000/"} Spawning runtime process
2024-02-24T07:42:19.472498Z [Deployer] INFO shuttle_proto::runtime: connecting runtime client
2024-02-24T07:42:19.478487Z [Runtime] shuttle-runtime executable started (version 0.39.0)
2024-02-24T07:42:19.478489Z [Runtime] ===============================================================
2024-02-24T07:42:19.478489Z [Runtime] Shuttle's default tracing subscriber is initialized!
2024-02-24T07:42:19.478490Z [Runtime] To disable the subscriber and use your own,
2024-02-24T07:42:19.478491Z [Runtime] turn off the default features for shuttle-runtime:
2024-02-24T07:42:19.478491Z [Runtime]
2024-02-24T07:42:19.478492Z [Runtime] shuttle-runtime = { version = "...", default-features = false }
2024-02-24T07:42:19.478492Z [Runtime] ===============================================================
2024-02-24T07:42:19.478633Z [Deployer] INFO shuttle_deployer::deployment::run: Loading resources
2024-02-24T07:42:19.478670Z [Deployer] INFO shuttle_deployer::persistence: {__self.project_id="01HQ7W881Z44R49MFJVDYBKK73"} Getting resources from resource-recorder
2024-02-24T07:42:19.480267Z [Deployer] INFO Entering Crashed state
2024-02-24T07:42:19.480269Z [Deployer] INFO Cleaning up startup crashed deployment
2024-02-24T07:42:19.480295Z [Deployer] ERROR shuttle_deployer::deployment::run: {error="Load error: Resource recorder error: status: Internal, message: \"could not verify project ownership\", details: [], metadata: MetadataMap { headers: {\"content-type\": \"application/grpc\", \"date\": \"Sat, 24 Feb 2024 07:42:19 GMT\", \"content-length\": \"0\"} }"} Service startup encountered an error
2024-02-24T07:42:19.471932Z [Deployer] INFO start_deployment
2024-02-24T07:42:19.472074Z [Deployer] INFO Entering Built state
2024-02-24T07:42:19.472076Z [Deployer] INFO Starting deployment
2024-02-24T07:42:19.472219Z [Deployer] INFO Entering Loading state
2024-02-24T07:42:19.472222Z [Deployer] INFO Loading resources
2024-02-24T07:42:19.472288Z [Deployer] INFO shuttle_service::runner: {args="/opt/shuttle/shuttle-builds/remove-box-rs/.shuttle-executables/28ac3c9e-cde5-413e-862c-2ac127b1edbb --port 20004 --provisioner-address http://provisioner:8000/ --env production --auth-uri http://auth:8000/"} Spawning runtime process
2024-02-24T07:42:19.472498Z [Deployer] INFO shuttle_proto::runtime: connecting runtime client
2024-02-24T07:42:19.478487Z [Runtime] shuttle-runtime executable started (version 0.39.0)
2024-02-24T07:42:19.478489Z [Runtime] ===============================================================
2024-02-24T07:42:19.478489Z [Runtime] Shuttle's default tracing subscriber is initialized!
2024-02-24T07:42:19.478490Z [Runtime] To disable the subscriber and use your own,
2024-02-24T07:42:19.478491Z [Runtime] turn off the default features for shuttle-runtime:
2024-02-24T07:42:19.478491Z [Runtime]
2024-02-24T07:42:19.478492Z [Runtime] shuttle-runtime = { version = "...", default-features = false }
2024-02-24T07:42:19.478492Z [Runtime] ===============================================================
2024-02-24T07:42:19.478633Z [Deployer] INFO shuttle_deployer::deployment::run: Loading resources
2024-02-24T07:42:19.478670Z [Deployer] INFO shuttle_deployer::persistence: {__self.project_id="01HQ7W881Z44R49MFJVDYBKK73"} Getting resources from resource-recorder
2024-02-24T07:42:19.480267Z [Deployer] INFO Entering Crashed state
2024-02-24T07:42:19.480269Z [Deployer] INFO Cleaning up startup crashed deployment
2024-02-24T07:42:19.480295Z [Deployer] ERROR shuttle_deployer::deployment::run: {error="Load error: Resource recorder error: status: Internal, message: \"could not verify project ownership\", details: [], metadata: MetadataMap { headers: {\"content-type\": \"application/grpc\", \"date\": \"Sat, 24 Feb 2024 07:42:19 GMT\", \"content-length\": \"0\"} }"} Service startup encountered an errorDuplicate declaration
- I have searched the issues and there are none like this.
jonaro00 commented
This is due to a security patch we released yesterday. The solution is to restart the project: cargo shuttle project restart
s-lambert commented
I've run cargo shuttle project restart, but it still crashes whenever it goes idle.
\"could not verify project ownership\", details: [], metadata: MetadataMap { headers: {\"content-type\": \"application/grpc\", \"date\": \"Sun, 25 Feb 2024 12:12:23 GMT\", \"content-length\": \"0\"} }"} Service startup encountered an error
Just to double check, I also reverted my code back to the initial hello world example that's generated and it still crashed.
Doing cargo shuttle project restart --idle-minutes 0 works by turning off the idle timing but is that OK as an interim fix?
Full log from the last deployment
2024-02-25T11:24:52.426990Z [Deployer] INFO Starting deployment
2024-02-25T11:24:52.427099Z [Deployer] INFO shuttle_deployer::handlers: Deployer version: 0.39.0
2024-02-25T11:24:52.427143Z [Deployer] INFO shuttle_deployer::handlers: Deployment ID: 5278f319-748e-47c9-986d-3ea28fea6735
2024-02-25T11:24:52.427153Z [Deployer] INFO shuttle_deployer::handlers: Service ID: 01HQAVHBQPW3YJH56N8P927YSH
2024-02-25T11:24:52.427161Z [Deployer] INFO shuttle_deployer::handlers: Service name: yeet
2024-02-25T11:24:52.427170Z [Deployer] INFO shuttle_deployer::handlers: Project ID: 01HQAV5BAS6XAY6AKQT5NB2B07
2024-02-25T11:24:52.427178Z [Deployer] INFO shuttle_deployer::handlers: Project name: yeet
2024-02-25T11:24:52.427190Z [Deployer] INFO shuttle_deployer::handlers: Date: 2024-02-25T11:24:52Z
2024-02-25T11:24:52.429718Z [Deployer] INFO Entering Queued state
2024-02-25T11:24:52.429725Z [Deployer] INFO Waiting for queue slot
2024-02-25T11:24:52.431937Z [Deployer] INFO Entering Building state
2024-02-25T11:24:52.431941Z [Deployer] INFO Building project
2024-02-25T11:24:52.431958Z [Deployer] INFO shuttle_deployer::deployment::queue: Extracting files
2024-02-25T11:24:52.433148Z [Deployer] INFO shuttle_deployer::deployment::queue: Building deployment
2024-02-25T11:24:52.724432Z [Deployer] INFO shuttle_service::builder: {name="yeet" deps="[\"shuttle-axum '^0.39.0'\", \"shuttle-runtime '^0.39.0'\", \"shuttle-secrets '^0.39.0'\"]"} Compiling workspace member with shuttle dependencies
2024-02-25T11:24:52.869519Z [Deployer] Compiling yeet v0.1.0 (/opt/shuttle/shuttle-builds/yeet)
2024-02-25T11:25:02.379221Z [Deployer] Finished release [optimized] target(s) in 9.62s
2024-02-25T11:25:02.391712Z [Deployer] INFO shuttle_deployer::deployment::queue: Running tests before starting up
2024-02-25T11:25:02.540415Z [Deployer] Compiling yeet v0.1.0 (/opt/shuttle/shuttle-builds/yeet)
2024-02-25T11:25:02.732050Z [Deployer] Finished release [optimized] target(s) in 0.31s
2024-02-25T11:25:02.740383Z [Deployer] Running unittests src/main.rs (target/release/deps/yeet-4ba2d07bca4757a2)
2024-02-25T11:25:02.741559Z [Deployer]
2024-02-25T11:25:02.741560Z [Deployer] running 0 tests
2024-02-25T11:25:02.741621Z [Deployer]
2024-02-25T11:25:02.741621Z [Deployer] test result: ok. 0 passed; 0 failed; 0 ignored; 0 measured; 0 filtered out; finished in 0.00s
2024-02-25T11:25:02.741622Z [Deployer]
2024-02-25T11:25:02.744364Z [Deployer] INFO shuttle_deployer::deployment::queue: Moving built executable
2024-02-25T11:25:02.760544Z [Deployer] INFO Releasing queue slot
2024-02-25T11:25:02.760998Z [Deployer] INFO Entering Built state
2024-02-25T11:25:02.761001Z [Deployer] INFO Starting deployment
2024-02-25T11:25:02.761179Z [Deployer] INFO Entering Loading state
2024-02-25T11:25:02.761183Z [Deployer] INFO Loading resources
2024-02-25T11:25:02.761252Z [Deployer] INFO shuttle_service::runner: {args="/opt/shuttle/shuttle-builds/yeet/.shuttle-executables/5278f319-748e-47c9-986d-3ea28fea6735 --port 19851 --provisioner-address http://provisioner:8000/ --env production --auth-uri http://auth:8000/"} Spawning runtime process
2024-02-25T11:25:02.761756Z [Deployer] INFO shuttle_proto::runtime: connecting runtime client
2024-02-25T11:25:02.768117Z [Runtime] shuttle-runtime executable started (version 0.39.0)
2024-02-25T11:25:02.768120Z [Runtime] ===============================================================
2024-02-25T11:25:02.768121Z [Runtime] Shuttle's default tracing subscriber is initialized!
2024-02-25T11:25:02.768121Z [Runtime] To disable the subscriber and use your own,
2024-02-25T11:25:02.768122Z [Runtime] turn off the default features for shuttle-runtime:
2024-02-25T11:25:02.768122Z [Runtime]
2024-02-25T11:25:02.768123Z [Runtime] shuttle-runtime = { version = "...", default-features = false }
2024-02-25T11:25:02.768123Z [Runtime] ===============================================================
2024-02-25T11:25:02.768198Z [Deployer] INFO shuttle_deployer::deployment::run: Loading resources
2024-02-25T11:25:02.768232Z [Deployer] INFO shuttle_deployer::persistence: {__self.project_id="01HQAV5BAS6XAY6AKQT5NB2B07"} Getting resources from resource-recorder
2024-02-25T11:25:02.782606Z [Runtime] TRACE shuttle_common::backends::auth: inserting public key from auth service into cache
2024-02-25T11:25:02.782613Z [Runtime] TRACE shuttle_common::claims: converting token to claim
2024-02-25T11:25:02.782759Z [Runtime] loading alpha service at /opt/shuttle/shuttle-builds/yeet/.shuttle-executables/5278f319-748e-47c9-986d-3ea28fea6735
2024-02-25T11:25:02.783512Z [Deployer] INFO shuttle_deployer::deployment::run: successfully loaded service
2024-02-25T11:25:02.783550Z [Deployer] INFO shuttle_deployer::persistence: Uploading resources to resource-recorder
2024-02-25T11:25:02.805510Z [Deployer] INFO Entering Running state
2024-02-25T11:25:02.805518Z [Deployer] INFO Starting service
2024-02-25T11:25:02.805907Z [Runtime] Starting on 0.0.0.0:8000
2024-02-25T11:25:02.805983Z [Deployer] INFO shuttle_deployer::deployment::run: Runtime started successully
2024-02-25T11:25:04.322443Z [Deployer] INFO get_deployment
2024-02-25T11:25:17.078660Z [Deployer] INFO get_logs
2024-02-25T11:29:37.270184Z [Deployer] INFO get_logs
2024-02-25T11:36:57.977150Z [Deployer] INFO get_logs
2024-02-25T11:37:05.064768Z [Deployer] INFO get_logs
2024-02-25T11:45:19.088865Z [Deployer] INFO get_logs
2024-02-25T12:12:23.972715Z [Deployer] INFO start_deployment
2024-02-25T12:12:23.972854Z [Deployer] INFO Entering Built state
2024-02-25T12:12:23.972855Z [Deployer] INFO Starting deployment
2024-02-25T12:12:23.973020Z [Deployer] INFO Entering Loading state
2024-02-25T12:12:23.973025Z [Deployer] INFO Loading resources
2024-02-25T12:12:23.973095Z [Deployer] INFO shuttle_service::runner: {args="/opt/shuttle/shuttle-builds/yeet/.shuttle-executables/5278f319-748e-47c9-986d-3ea28fea6735 --port 18700 --provisioner-address http://provisioner:8000/ --env production --auth-uri http://auth:8000/"} Spawning runtime process
2024-02-25T12:12:23.973284Z [Deployer] INFO shuttle_proto::runtime: connecting runtime client
2024-02-25T12:12:23.991349Z [Runtime] shuttle-runtime executable started (version 0.39.0)
2024-02-25T12:12:23.991351Z [Runtime] ===============================================================
2024-02-25T12:12:23.991352Z [Runtime] Shuttle's default tracing subscriber is initialized!
2024-02-25T12:12:23.991353Z [Runtime] To disable the subscriber and use your own,
2024-02-25T12:12:23.991353Z [Runtime] turn off the default features for shuttle-runtime:
2024-02-25T12:12:23.991353Z [Runtime]
2024-02-25T12:12:23.991354Z [Runtime] shuttle-runtime = { version = "...", default-features = false }
2024-02-25T12:12:23.991355Z [Runtime] ===============================================================
2024-02-25T12:12:23.991446Z [Deployer] INFO shuttle_deployer::deployment::run: Loading resources
2024-02-25T12:12:23.991482Z [Deployer] INFO shuttle_deployer::persistence: {__self.project_id="01HQAV5BAS6XAY6AKQT5NB2B07"} Getting resources from resource-recorder
2024-02-25T12:12:23.992772Z [Deployer] INFO Entering Crashed state
2024-02-25T12:12:23.992774Z [Deployer] INFO Cleaning up startup crashed deployment
2024-02-25T12:12:23.992801Z [Deployer] ERROR shuttle_deployer::deployment::run: {error="Load error: Resource recorder error: status: Internal, message: \"could not verify project ownership\", details: [], metadata: MetadataMap { headers: {\"content-type\": \"application/grpc\", \"date\": \"Sun, 25 Feb 2024 12:12:23 GMT\", \"content-length\": \"0\"} }"} Service startup encountered an error
djmango commented
Confirmed, also seeing
2024-02-25T23:05:09.251176Z [Deployer] ERROR shuttle_deployer::deployment::run: {error="Load error: Resource recorder error: status: Internal, message: \"could not verify project ownership\", details: [], metadata: MetadataMap { headers: {\"content-type\": \"application/grpc\", \"date\": \"Sun, 25 Feb 2024 23:05:09 GMT\", \"content-length\": \"0\"} }"} Service startup encountered an error
Going to try @s-lambert fix setting idle minutes to 0
jonaro00 commented
@s-lambert @djmango Earlier today, we fixed a follow-up issue from the patch release that fixes crashes when waking up from idle. No restart needed (unless changing the idle setting).
chesedo commented
Our patch yesterday should have fixed this error. Feel free to re-open the issue if it did not 😄