Deploying app suddenly takes 15 minutes

Questions / Help
1

I’m using version 283 of flyctl, and when deploying my rails app it takes about 15 minutes after this output:

=> Verifying app config
--> Verified app config
==> Building image
Remote builder REDACTED ready
==> Building image with Buildpacks
--> docker host: 20.10.12 linux x86_64
20: Pulling from heroku/buildpacks
Digest: sha256:51aca0a832691a38064bbc95db2bf503e4aead68a2201919606d424873549594
Status: Image is up to date for heroku/buildpacks:20
20: Pulling from heroku/pack
Digest: sha256:d69753bedaabfdc0321ba4aaa670189371b92cf30649e7f0bd5586398fe3f0c5
Status: Image is up to date for heroku/pack:20

Any idea how what might cause this long waiting time?

The deploy ends up finishing fine. But before the deploy was about 1 minute in total.

2

Do you know which part of the build was taking the most time?

3

The only thing I know is that the last output of the command before it halts for over 10 minutes is

20: Pulling from heroku/pack
Digest: sha256:d69753bedaabfdc0321ba4aaa670189371b92cf30649e7f0bd5586398fe3f0c5
Status: Image is up to date for heroku/pack:20

If you have any advice as to where I can find more information on what part of the build was taking most time, please let me know.

4

How big is your directory? After that Image is up to date, the buildpack does a whole bunch of processing before it moves along. That should be cached, though, and only happen when the Heroku Buildpack gets updated.

5

The size didn’t change and it’s practically a newly generated Rails application. Also, it takes this long everytime I deploy. So that doesn’t seem to be the problem here.

Anybody else any idea? Fly is pretty much unusable this way.

6

Bumping this issue… I hope this is due to my own setup, because I was really starting to like Fly.io.

However, with the current state there is no way to use the platform efficiently and I have no idea how to solve this.

7

@catadesk Can you try the following steps and provide all logs?

fly agent stop
LOG_LEVEL=debug fly agent daemon-start

and in a different terminal

LOG_LEVEL=debug fly deploy

This should give us a lot more information about what’s going on. You should get plenty of logs from both the agent and the deploy process.

The agent logs should be of most interest when it stalls.

8

Thanks for helping out @jerome, it took me a while but I’ve done what you said.

On the agent terminal:

% LOG_LEVEL=debug fly agent daemon-start

DEBUG Loaded flyctl config from/local/path/.fly/config.yml

DEBUG determined hostname: "name-of-my-pc"

DEBUG determined working directory: "/local/path/app-name"

DEBUG determined user home directory: "/local/path"

DEBUG determined config directory: "/local/path/.fly"

DEBUG ensured config directory exists.

DEBUG ensured config directory perms.

DEBUG cache loaded.

DEBUG config initialized.

DEBUG initialized task manager.

DEBUG started querying for new release

DEBUG client initialized.

DEBUG Working Directory: /local/path/to/working/dir

DEBUG App Config File:

2022/01/26 20:01:17 [13861] OK 13861

DEBUG querying for release resulted to v0.0.288

2022/01/26 20:01:36 [13861] config change at: 2022-01-26 20:01:36.864930195 +0100 CET

2022/01/26 20:01:36 [13861] incoming command: [ping]

2022/01/26 20:01:36 [13861] incoming command: [establish personal]

DEBUG --> POST https://api.fly.io/graphql {{"query":"query($orgType: OrganizationType) { organizations(type: $orgType) { nodes { id slug name type } } }","variables":null}

}

DEBUG <-- 200 https://api.fly.io/graphql (973.6ms) {"data":{"organizations":{"nodes":[{"id":"gRmL097XkZmgAuKRKJ4v6VY4v0Cm9q","slug":"personal","name":"Rene van Pelt","type":"PERSONAL"},{"id":"L5q73MAjNyqbYHmxmNBa290BaYuBAZ","slug":"catadesk","name":"Catadesk","type":"SHARED"}]}}}

wg connect fdaa:0:4354::3 ams1.gateway.6pn.dev:51820 fdaa:0:4354:a7b:16a9:0:a:0 fdaa:0:4354::

2022/01/26 20:01:37 [13861] incoming command: [probe personal]

DEBUG Probing WireGuard connectivity

DEBUG probe results for _apps.internal[app-name,app-name-postgres]

2022/01/26 20:01:38 [13861] incoming command: [connect personal [fdaa:0:4354:a7b:23c5:0:733a:2]:2375 0]

2022/01/26 20:01:38 [13861] incoming connect: [connect personal [fdaa:0:4354:a7b:23c5:0:733a:2]:2375 0]

DEBUG --> POST https://api.fly.io/graphql {{"query":"mutation($input: ValidateWireGuardPeersInput!) { validateWireGuardPeers(input: $input) { invalidPeerIps } }","variables":{"input":{"peerIps":["fdaa:0:45b4:a7b:16a9:0:a:2","fdaa:0:4354:a7b:16a9:0:a:2"]}}}

}

DEBUG <-- 200 https://api.fly.io/graphql (1.68s) {"data":{"validateWireGuardPeers":{"invalidPeerIps":[]}}}

2022/01/26 20:03:19 [13861] validated wireguard peers(stat)

DEBUG --> POST https://api.fly.io/graphql {{"query":"mutation($input: ValidateWireGuardPeersInput!) { validateWireGuardPeers(input: $input) { invalidPeerIps } }","variables":{"input":{"peerIps":["fdaa:0:45b4:a7b:16a9:0:a:2","fdaa:0:4354:a7b:16a9:0:a:2"]}}}

}

DEBUG <-- 200 https://api.fly.io/graphql (380.79ms) {"data":{"validateWireGuardPeers":{"invalidPeerIps":[]}}}

2022/01/26 20:05:17 [13861] validated wireguard peers(stat)

DEBUG --> POST https://api.fly.io/graphql {{"query":"mutation($input: ValidateWireGuardPeersInput!) { validateWireGuardPeers(input: $input) { invalidPeerIps } }","variables":{"input":{"peerIps":["fdaa:0:45b4:a7b:16a9:0:a:2","fdaa:0:4354:a7b:16a9:0:a:2"]}}}

}

DEBUG <-- 200 https://api.fly.io/graphql (635.74ms) {"data":{"validateWireGuardPeers":{"invalidPeerIps":[]}}}

2022/01/26 20:07:18 [13861] validated wireguard peers(stat)

DEBUG --> POST https://api.fly.io/graphql {{"query":"mutation($input: ValidateWireGuardPeersInput!) { validateWireGuardPeers(input: $input) { invalidPeerIps } }","variables":{"input":{"peerIps":["fdaa:0:45b4:a7b:16a9:0:a:2","fdaa:0:4354:a7b:16a9:0:a:2"]}}}

}

DEBUG <-- 200 https://api.fly.io/graphql (647.36ms) {"data":{"validateWireGuardPeers":{"invalidPeerIps":[]}}}

2022/01/26 20:09:18 [13861] validated wireguard peers(stat)

DEBUG --> POST https://api.fly.io/graphql {{"query":"mutation($input: ValidateWireGuardPeersInput!) { validateWireGuardPeers(input: $input) { invalidPeerIps } }","variables":{"input":{"peerIps":["fdaa:0:45b4:a7b:16a9:0:a:2","fdaa:0:4354:a7b:16a9:0:a:2"]}}}

}

DEBUG <-- 200 https://api.fly.io/graphql (858.6ms) {"data":{"validateWireGuardPeers":{"invalidPeerIps":[]}}}

2022/01/26 20:11:18 [13861] validated wireguard peers(stat)

2022/01/26 20:11:52 [13861] config change at: 2022-01-26 20:11:18.235934223 +0100 CET

2022/01/26 20:11:52 [13861] incoming command: [connect personal [fdaa:0:4354:a7b:23c5:0:733a:2]:2375 0]

2022/01/26 20:11:52 [13861] incoming connect: [connect personal [fdaa:0:4354:a7b:23c5:0:733a:2]:2375 0]

2022/01/26 20:11:52 [13861] err handling connect: connection failed: connect tcp [fdaa:0:4354:a7b:23c5:0:733a:2]:2375: connection was refused

2022/01/26 20:11:52 [13861] incoming command: [connect personal [fdaa:0:4354:a7b:23c5:0:733a:2]:2375 0]

2022/01/26 20:11:52 [13861] incoming connect: [connect personal [fdaa:0:4354:a7b:23c5:0:733a:2]:2375 0]

2022/01/26 20:11:52 [13861] err handling connect: connection failed: connect tcp [fdaa:0:4354:a7b:23c5:0:733a:2]:2375: connection was refused

2022/01/26 20:11:52 [13861] incoming command: [connect personal [fdaa:0:4354:a7b:23c5:0:733a:2]:2375 0]

2022/01/26 20:11:52 [13861] incoming connect: [connect personal [fdaa:0:4354:a7b:23c5:0:733a:2]:2375 0]

2022/01/26 20:11:52 [13861] err handling connect: connection failed: connect tcp [fdaa:0:4354:a7b:23c5:0:733a:2]:2375: connection was refused

2022/01/26 20:11:52 [13861] incoming command: [connect personal [fdaa:0:4354:a7b:23c5:0:733a:2]:2375 0]

2022/01/26 20:11:52 [13861] incoming connect: [connect personal [fdaa:0:4354:a7b:23c5:0:733a:2]:2375 0]

2022/01/26 20:11:52 [13861] err handling connect: connection failed: connect tcp [fdaa:0:4354:a7b:23c5:0:733a:2]:2375: connection was refused

2022/01/26 20:11:52 [13861] incoming command: [connect personal [fdaa:0:4354:a7b:23c5:0:733a:2]:2375 0]

2022/01/26 20:11:52 [13861] incoming connect: [connect personal [fdaa:0:4354:a7b:23c5:0:733a:2]:2375 0]

2022/01/26 20:11:52 [13861] err handling connect: connection failed: connect tcp [fdaa:0:4354:a7b:23c5:0:733a:2]:2375: connection was refused

And on the deploy terminal:

% LOG_LEVEL=debug fly deploy

DEBUG Loaded flyctl config from/local/path/.fly/config.yml
DEBUG determined hostname: "my-pc-name"
DEBUG determined working directory: "/local/path/app-name"
DEBUG determined user home directory: "/local/path"
DEBUG determined config directory: "/local/path/.fly"
DEBUG ensured config directory exists.
DEBUG ensured config directory perms.
DEBUG cache loaded.
DEBUG config initialized.
DEBUG initialized task manager.
DEBUG started querying for new release
DEBUG client initialized.
DEBUG app config loaded from /local/path/app-name/fly.toml
==> Verifying app config
--> Verified app config
==> Building image
DEBUG trying local docker daemon
DEBUG Local docker daemon unavailable
DEBUG trying remote docker daemon
DEBUG Reporting buildDEBUG --> POST https://api.fly.io/graphql {{"query":"mutation($input: StartSourceBuildInput!) { startSourceBuild(input: $input) { sourceBuild { id } } }","variables":{"input":{"appId":"app-name"}}}
}
DEBUG <-- 200 https://api.fly.io/graphql (388.08ms) {"errors":[{"message":"StartSourceBuildInput isn't a defined input type (on $input)","locations":[{"line":1,"column":10}],"path":["mutation"],"extensions":{"code":"variableRequiresValidType","typeName":"StartSourceBuildInput","variableName":"input"}},{"message":"Field 'startSourceBuild' doesn't exist on type 'Mutations'","locations":[{"line":1,"column":44}],"path":["mutation","startSourceBuild"],"extensions":{"code":"undefinedField","typeName":"Mutations","fieldName":"startSourceBuild"}},{"message":"Variable $input is declared by anonymous mutation but not used","locations":[{"line":1,"column":1}],"path":["mutation"],"extensions":{"code":"variableNotUsed","variableName":"input"}}]}
DEBUG Failed storing buildDEBUG Trying 'Buildpacks' strategy
DEBUG --> POST https://api.fly.io/graphql {{"query":"mutation($input: EnsureMachineRemoteBuilderInput!) { ensureMachineRemoteBuilder(input: $input) { machine { id state ips { nodes { family kind ip } } }, app { name organization { slug } } } }","variables":{"input":{"appName":"app-name","organizationId":null}}}
}
DEBUG querying for release resulted to v0.0.288
DEBUG <-- 200 https://api.fly.io/graphql (2.14s) {"data":{"ensureMachineRemoteBuilder":{"machine":{"id":"82573f73","state":"starting","ips":{"nodes":[{"family":"v6","kind":"privatenet","ip":"fdaa:0:4354:a7b:23c5:0:733a:2"},{"family":"v6","kind":"public","ip":"2604:1380:4601:d603::733a:3"},{"family":"v4","kind":"private","ip":"172.19.4.42"}]}},"app":{"name":"fly-builder-delicate-glade-8730","organization":{"slug":"personal"}}}}}
DEBUG checking ip &{Family:v6 Kind:privatenet IP:fdaa:0:4354:a7b:23c5:0:733a:2 MaskSize:0}
Waiting for remote builder fly-builder-delicate-glade-8730... connecting ⣾ DEBUG --> POST https://api.fly.io/graphql {{"query":"query ($appName: String!) { app(name: $appName) { id name hostname deployed status version appUrl config { definition } organization { id slug } services { description protocol internalPort ports { port handlers } } ipAddresses { nodes { id address type createdAt } } imageDetails { repository version } } }","variables":{"appName":"app-name"}}
}
Waiting for remote builder fly-builder-delicate-glade-8730... connecting ⣷ DEBUG <-- 200 https://api.fly.io/graphql (1.94s) {"data":{"app":{"id":"app-name","name":"app-name","hostname":"app-name.fly.dev","deployed":true,"status":"running","version":20,"appUrl":"https://213.188.207.84","config":{"definition":{"kill_timeout":5,"kill_signal":"SIGINT","processes":[],"deploy":{"release_command":"bundle exec rails db:migrate"},"experimental":{"allowed_public_ports":[],"entrypoint":[],"cmd":[],"exec":[],"auto_rollback":true},"services":[{"processes":["app"],"protocol":"tcp","internal_port":8080,"concurrency":{"soft_limit":20,"hard_limit":25,"type":"connections"},"ports":[{"port":80,"handlers":["http"]},{"port":443,"handlers":["tls","http"]}],"tcp_checks":[{"interval":"15s","timeout":"2s","grace_period":"1s","restart_limit":0}],"http_checks":[],"script_checks":[]}],"env":{"API_BASE_URL":"https://app-name.fly.dev/tags","PORT":"8080"}}},"organization":{"id":"org_id","slug":"personal"},"services":[{"description":"TCP 80/443 ⇢ 8080","protocol":"TCP","internalPort":8080,"ports":[{"port":80,"handlers":["HTTP"]},{"port":443,"handlers":["TLS","HTTP"]}]}],"ipAddresses":{"nodes":[{"id":"D361ODBOn4xgjT4vxLlw9O4Aw9uggXDLb","address":"213.188.207.84","type":"v4","createdAt":"2022-01-09T19:32:58Z"},{"id":"YJ8oKgaKkzVn3TlNJLo8Bal28BiLoQQYL","address":"2a09:8280:1::1:1938","type":"v6","createdAt":"2022-01-09T19:32:58Z"}]},"imageDetails":{"repository":"app-name","version":null}}}}
DEBUG --> POST https://api.fly.io/graphql {{"query":"mutation($input: ValidateWireGuardPeersInput!) { validateWireGuardPeers(input: $input) { invalidPeerIps } }","variables":{"input":{"peerIps":["fdaa:0:45b4:a7b:16a9:0:a:2","fdaa:0:4354:a7b:16a9:0:a:2"]}}}
}
Waiting for remote builder fly-builder-delicate-glade-8730... connecting ⣾ DEBUG <-- 200 https://api.fly.io/graphql (136.95ms) {"data":{"validateWireGuardPeers":{"invalidPeerIps":[]}}}
Waiting for remote builder fly-builder-delicate-glade-8730... connecting ⣷ DEBUG Remote builder available, but pinging again in 200ms to be sure
Waiting for remote builder fly-builder-delicate-glade-8730... connecting ⣾ DEBUG Remote builder available, but pinging again in 224.36011ms to be sure
Waiting for remote builder fly-builder-delicate-glade-8730... connecting ⣽ DEBUG Remote builder available, but pinging again in 236.856607ms to be sure
Waiting for remote builder fly-builder-delicate-glade-8730... connecting ⣻ DEBUG Remote builder available, but pinging again in 215.863416ms to be sure
Waiting for remote builder fly-builder-delicate-glade-8730... connecting ⢿ DEBUG Remote builder is ready to build!
Remote builder fly-builder-delicate-glade-8730 ready
==> Building image with Buildpacks
--> docker host: 20.10.12 linux x86_64
Pulling image index.docker.io/heroku/buildpacks:20
20: Pulling from heroku/buildpacks
Digest: sha256:b62cf879f425edc3fe62d52205fb40b9d603403ab1ff3e03bb94641babef597d
Status: Image is up to date for heroku/buildpacks:20
Selected run image heroku/pack:20
Pulling image heroku/pack:20
20: Pulling from heroku/pack
Digest: sha256:417df364dc0e2b1016021e982ef19fb34cbce7b03b378b1e46bfa6346db676bd
Status: Image is up to date for heroku/pack:20
Creating builder with the following buildpacks:
-> heroku/java@0.3.14
-> heroku/gradle@0.0.35
-> heroku/jvm@0.1.12
-> heroku/maven@0.2.5
-> heroku/procfile@0.6.2
-> heroku/scala@0.0.90
-> heroku/java-function@0.3.26
-> heroku/jvm@0.1.12
-> heroku/jvm-function-invoker@0.6.0
-> heroku/maven@0.2.5
-> heroku/ruby@0.1.3
-> heroku/procfile@0.6.2
-> heroku/python@0.3.1
-> heroku/php@0.3.1
-> heroku/go@0.3.1
-> heroku/nodejs@0.4.0
-> heroku/nodejs-engine@0.7.4
-> heroku/nodejs-npm@0.4.4
-> heroku/nodejs-yarn@0.1.8
-> heroku/procfile@0.6.2
-> heroku/nodejs-function@0.7.0
-> heroku/nodejs-engine@0.7.4
-> heroku/nodejs-function-invoker@0.2.8
-> heroku/nodejs-npm@0.4.4
Using build cache volume pack-cache-app-name_cache-87fe13434346.build
Running the creator on OS linux with:
Container Settings:
  Args: /cnb/lifecycle/creator -daemon -launch-cache /launch-cache -log-level debug -app /workspace -cache-dir /cache -run-image heroku/pack:20 -tag registry.fly.io/app-name:deployment-1643223692 -gid 0 registry.fly.io/app-name:cache
  System Envs: CNB_PLATFORM_API=0.6
  Image: pack.local/builder/686c73797a6b6c767169:latest
  User: root
  Labels: map[author:pack]
Host Settings:
  Binds: pack-cache-app-name_cache-87fe13434346.build:/cache /var/run/docker.sock:/var/run/docker.sock pack-cache-app-name_cache-87fe13434346.launch:/launch-cache pack-layers-mgxrblcfuj:/layers pack-app-rapvybsmip:/workspace
  Network Mode: 

DEBUG result image:<nil> error:executing lifecycle: io: read/write on closed pipe
Error failed to fetch an image or build from source: executing lifecycle: io: read/write on closed pipe

I didn’t get much wiser from it, but maybe you do?

9

A little bit.

Can you tell us in what country / state you’re located?

And can you tell us what “gateway” you’re connecting to? This information should be available in your ~/.fly/config.yml under wire_guard_state.<your-org>.region.

10

So sorry for the late reply, never saw your question.

We’re still not using fly because we’re running into problems. So it might be wise to answer this still. I’m in the Netherlands, and my ./fly/config.yml says:

endpointip: ams1.gateway.6pn.dev

11

Try running fly wireguard websockets enable and see if that helps? This helps in a lot of scenarios where an ISP or firewall is interfering with UDP wireguard packets.

1 Like