Timeout while executing tugboat wait

[juasiepo]

Hi

I am having the following error:

tugboat create do6.example.com -i 303619 -r 2 -k 32527
Queueing creation of droplet 'do6.example.com'...done
tugboat wait do6.example.com --state active
Droplet fuzzy name provided. Finding droplet ID...done, 664699 (do6.eltorete.com)
Waiting for droplet to become active.........../usr/lib/ruby/1.9.1/net/http.rb:762:in `initialize': Connection timed out - connect(2) (Errno::ETIMEDOUT)
        from /usr/lib/ruby/1.9.1/net/http.rb:762:in `open'
        from /usr/lib/ruby/1.9.1/net/http.rb:762:in `block in connect'
        from /usr/lib/ruby/1.9.1/timeout.rb:54:in `timeout'
        from /usr/lib/ruby/1.9.1/timeout.rb:99:in `timeout'
        from /usr/lib/ruby/1.9.1/net/http.rb:762:in `connect'
        from /usr/lib/ruby/1.9.1/net/http.rb:755:in `do_start'
        from /usr/lib/ruby/1.9.1/net/http.rb:744:in `start'

It would be very useful if the timeout parameter could be modified on the command line.
tugboat wait do6.example.com --timeout 300 --state active

Thank you

[petems]

Hi!

Good idea, we could probably up the default timeout as well in the ~/.tugboat config file for when it takes longer than normal.

Was this a one-off issue or did it happen consistently?

[pearkes]

DO can occasionally take a really long time to make droplet event changes, it's pretty irregular. Totally agree we should do a timeout here, and probably raise the default as it is to 500-600.

[pearkes]

Also, configuration in the ~/.tugboat also makes total sense. :)

[petems]

Haven't done much work on tugboat for a while, so I'll pick this up over the weekend 👍

[rockymadden]

This would be wonderful, as I regularly run into a similar issue which could be addressed via passing timeout options to faraday:

Waiting for droplet to become active...................../home/ubuntu/.rvm/rubies/ruby-1.9.3-p448/lib/ruby/1.9.1/net/protocol.rb:146:in `rescue in rbuf_fill': Timeout::Error (Faraday::TimeoutError)
    from /home/ubuntu/.rvm/rubies/ruby-1.9.3-p448/lib/ruby/1.9.1/net/protocol.rb:140:in `rbuf_fill'
    from /home/ubuntu/.rvm/rubies/ruby-1.9.3-p448/lib/ruby/1.9.1/net/protocol.rb:122:in `readuntil'
    from /home/ubuntu/.rvm/rubies/ruby-1.9.3-p448/lib/ruby/1.9.1/net/protocol.rb:132:in `readline'
    from /home/ubuntu/.rvm/rubies/ruby-1.9.3-p448/lib/ruby/1.9.1/net/http.rb:2563:in `read_status_line'
    from /home/ubuntu/.rvm/rubies/ruby-1.9.3-p448/lib/ruby/1.9.1/net/http.rb:2552:in `read_new'
    from /home/ubuntu/.rvm/rubies/ruby-1.9.3-p448/lib/ruby/1.9.1/net/http.rb:1320:in `block in transport_request'
    from /home/ubuntu/.rvm/rubies/ruby-1.9.3-p448/lib/ruby/1.9.1/net/http.rb:1317:in `catch'
    from /home/ubuntu/.rvm/rubies/ruby-1.9.3-p448/lib/ruby/1.9.1/net/http.rb:1317:in `transport_request'
    from /home/ubuntu/.rvm/rubies/ruby-1.9.3-p448/lib/ruby/1.9.1/net/http.rb:1294:in `request'
    from /home/ubuntu/.rvm/rubies/ruby-1.9.3-p448/lib/ruby/1.9.1/net/http.rb:1287:in `block in request'
    from /home/ubuntu/.rvm/rubies/ruby-1.9.3-p448/lib/ruby/1.9.1/net/http.rb:746:in `start'
    from /home/ubuntu/.rvm/rubies/ruby-1.9.3-p448/lib/ruby/1.9.1/net/http.rb:1285:in `request'
    from /home/ubuntu/.rvm/rubies/ruby-1.9.3-p448/lib/ruby/1.9.1/net/http.rb:1027:in `get'
    from /home/ubuntu/.rvm/gems/ruby-1.9.3-p448/gems/faraday-0.9.2/lib/faraday/adapter/net_http.rb:80:in `perform_request'
    from /home/ubuntu/.rvm/gems/ruby-1.9.3-p448/gems/faraday-0.9.2/lib/faraday/adapter/net_http.rb:40:in `block in call'
    from /home/ubuntu/.rvm/gems/ruby-1.9.3-p448/gems/faraday-0.9.2/lib/faraday/adapter/net_http.rb:87:in `with_net_http_connection'
    from /home/ubuntu/.rvm/gems/ruby-1.9.3-p448/gems/faraday-0.9.2/lib/faraday/adapter/net_http.rb:32:in `call'
    from /home/ubuntu/.rvm/gems/ruby-1.9.3-p448/gems/faraday-0.9.2/lib/faraday/rack_builder.rb:139:in `build_response'
    from /home/ubuntu/.rvm/gems/ruby-1.9.3-p448/gems/faraday-0.9.2/lib/faraday/connection.rb:377:in `run_request'
    from /home/ubuntu/.rvm/gems/ruby-1.9.3-p448/gems/faraday-0.9.2/lib/faraday/connection.rb:140:in `get'
    from /home/ubuntu/.rvm/gems/ruby-1.9.3-p448/gems/barge-0.10.0/lib/barge/resource/base.rb:22:in `public_send'
    from /home/ubuntu/.rvm/gems/ruby-1.9.3-p448/gems/barge-0.10.0/lib/barge/resource/base.rb:22:in `request'
    from /home/ubuntu/.rvm/gems/ruby-1.9.3-p448/gems/barge-0.10.0/lib/barge/resource/base.rb:16:in `block (2 levels) in <module:Base>'
    from /home/ubuntu/.rvm/gems/ruby-1.9.3-p448/gems/barge-0.10.0/lib/barge/resource/droplet.rb:15:in `show'
    from /home/ubuntu/.rvm/gems/ruby-1.9.3-p448/gems/tugboat-2.0.1/lib/tugboat/middleware/wait_for_state.rb:22:in `call'
    from /home/ubuntu/.rvm/gems/ruby-1.9.3-p448/gems/tugboat-2.0.1/lib/tugboat/middleware/find_droplet.rb:151:in `call'
    from /home/ubuntu/.rvm/gems/ruby-1.9.3-p448/gems/tugboat-2.0.1/lib/tugboat/middleware/inject_client.rb:27:in `call'
    from /home/ubuntu/.rvm/gems/ruby-1.9.3-p448/gems/tugboat-2.0.1/lib/tugboat/middleware/check_configuration.rb:19:in `call'
    from /home/ubuntu/.rvm/gems/ruby-1.9.3-p448/gems/tugboat-2.0.1/lib/tugboat/middleware/inject_configuration.rb:10:in `call'
    from /home/ubuntu/.rvm/gems/ruby-1.9.3-p448/gems/middleware-0.1.0/lib/middleware/runner.rb:31:in `call'
    from /home/ubuntu/.rvm/gems/ruby-1.9.3-p448/gems/middleware-0.1.0/lib/middleware/builder.rb:102:in `call'
    from /home/ubuntu/.rvm/gems/ruby-1.9.3-p448/gems/tugboat-2.0.1/lib/tugboat/cli.rb:528:in `wait'
    from /home/ubuntu/.rvm/gems/ruby-1.9.3-p448/gems/thor-0.18.1/lib/thor/command.rb:27:in `run'
    from /home/ubuntu/.rvm/gems/ruby-1.9.3-p448/gems/thor-0.18.1/lib/thor/invocation.rb:120:in `invoke_command'
    from /home/ubuntu/.rvm/gems/ruby-1.9.3-p448/gems/thor-0.18.1/lib/thor.rb:363:in `dispatch'
    from /home/ubuntu/.rvm/gems/ruby-1.9.3-p448/gems/thor-0.18.1/lib/thor/base.rb:439:in `start'
    from /home/ubuntu/.rvm/gems/ruby-1.9.3-p448/gems/tugboat-2.0.1/bin/tugboat:10:in `<top (required)>'
    from /home/ubuntu/.rvm/gems/ruby-1.9.3-p448/bin/tugboat:23:in `load'
    from /home/ubuntu/.rvm/gems/ruby-1.9.3-p448/bin/tugboat:23:in `<main>'

[petems]

Wow, this is over 2 years old now, should probably get to to work on this!

@rockymadden Just curious, how long did it take for the machine to come up in the end did you ever find out?

[petems]

@rockymadden Also, can you give me an example of something that triggers a timeout? I think I've fixed the issue but it's hard to write tests for!

[rockymadden]

@petems The droplets came up in a timely fashion (e.g. ~60 seconds), but tugboat wait would randomly error with the above just a few ticks in (e.g. 15 seconds to 45 seconds). Seeing it many times over the past few days, I believe the issue was/is purely on CircleCI and/or DigitalOcean's and that altering read_timeout or continue_timeout would help handle for the edge cases. However, that is purely speculation as it is really hard to reliably predict/troubleshoot. I ended up sleeping for 60 seconds after droplet creation before issuing tugboat wait which doesn't fix the problem outright but reduces how often it comes up by 99%+.

I have all the logs in CircleCI, and I can turn the logging up on tugboat and send along those to you when I run across it next if that would help. :) You can kinda get a picture of what we are doing here:

TL;DR: Each GitHub push/commit we use CircleCI to create a minimally representative version of the cloud on DO, run tests to ensure they pass, and then destroy the cloud on DO. Because the CircleCI lifecycle does not have all the features we need, I made the equivalent in bash (e.g. I want a teardown step to always destroy the cloud, we have different cloud types we need to test for, etc).

[petems]

Ah ok. I tried turning a droplet off and trying to get digitalocean to timeout on that, but that seems ok. It might be the size of the droplet means the requests take more than the default 10 seconds, let me try making a biiiiiig droplet to see if I can recreate the issue!

BTW, Fog now has API 2.0 support for DO so it might be better for what you're trying to do here? Tugboat is more of a cli tool, it might be better to abstract your script to Fog?

[petems]

I still can't recreate, even when trying a 16GB droplet:

bundle exec tugboat create bigtestdroplet -s 16GB && bundle exec tugboat wait bigtestdroplet --state=active
Queueing creation of droplet 'bigtestdroplet'...Droplet created!
Droplet fuzzy name provided. Finding droplet ID...done, 9159953 (bigtestdroplet)
Waiting for droplet to become active........................done (53s)

What image are you using to create it, is it something custom?

[rockymadden]

I am still able to semi-reliably recreate the issue. Let me do this, I'll create an ad-hoc public circleci repo that shows the behavior in a repeatable fashion (and give you repo/circleci access, if you wish). I can then include your timeout changes to see if it fixes it. Hopefully we can make a test for it in tugboat itself from what we learn.

[rockymadden]

BTW, I am not surprised you cannot recreate it with a single wait test. It only seems to show after several creates/waits:

[petems]

Got some basic ideas for having timeout as a config option here, should finish work on it soon:

https://github.com/pearkes/tugboat/tree/allow_timeout_setting

[petems]

Timeout setting added in #281, and 4.0.0 switches to DropletKit which anecdotally seems to fix some of the timeout issues.

This is fairly old so I'm going to close this one for now. If this is still an issue can you open a new issue for me and we can work further on it.