Rails One-Click times out after a git pull containing four files. accessing my site is a 504: Gateway Timeout

May 30, 2017 2k views
Ruby on Rails Deployment Nginx Ubuntu 16.04
jcspampinato
By:
jcspampinato

So, made some small changes to some files, the largest of which was the creation of a new javascript file and moving an existing javascript function to it. Committed them locally, pushed them to my remote master, then did a pull from my DO droplet. Ever since then, my site will not load in a client browser. The browser attempts to load the page and then produces an nginx 504 Gateway timeout message.

Server is running and pings. I can ssh to it.

Output of sudo systemctl status unicorn:
<^>unicorn.service - "DigitalOcean Rails One-Click Application"
Loaded: loaded (/etc/systemd/system/unicorn.service; enabled; vendor preset: enabled)
Active: active (running) since Tue 2017-05-30 20:40:45 UTC; 6min ago
Main PID: 29346 (bash)
Tasks: 5
Memory: 68.4M
CPU: 6min 53.943s
CGroup: /system.slice/unicorn.service
├─ 6026 unicornrails worker[0] -E production -c ./config/unicorn.rb

├─29346 /bin/bash /home/rails/popEFX/.unicorn.sh
└─29512 unicornrails master -E production -c ./config/unicorn.rb

May 30 20:40:45 popEFX-ruby-rails-2gb-nyc2-01 systemd[1]: Started "DigitalOcean Rails One-Click Application".
May 30 20:40:45 popEFX-ruby-rails-2gb-nyc2-01 DigitalOceanRailsOneClick[29346]: Using /usr/local/rvm/gems/ruby-2.4.0
<^>

Output of sudo tail /var/log/unicorn/unicorn.log is over two weeks old

<^>I, [2017-05-14T22:33:20.394874 #2329] INFO -- : reaped #<Process::Status: pid 2331 exit 0> worker=0
I, [2017-05-14T22:33:20.395933 #2329] INFO -- : reaped #<Process::Status: pid 2334 exit 0> worker=1
I, [2017-05-14T22:33:20.396801 #2329] INFO -- : reaped #<Process::Status: pid 2337 exit 0> worker=2
I, [2017-05-14T22:33:20.397624 #2329] INFO -- : reaped #<Process::Status: pid 2340 exit 0> worker=3
Exception `Errno::ECHILD' at /home/rails/railsproject/vendor/bundle/gems/unicorn-5.3.0/lib/unicorn/httpserver.rb:399 - No child processes
I, [2017-05-14T22:33:20.397810 #2329] INFO -- : master complete<^>

Output of sudo tail /var/log/nginx/error.log
<^>2017/05/30 20:30:37 [notice] 2126#2126: signal process started
2017/05/30 20:32:05 [error] 2135#2135: *46 upstream timed out (110: Connection timed out) while reading response header from upstream, client: 74.109.5.103, server: _, request: "GET / HTTP/1.1", upstream: "http://unix:/run/DigitalOceanOneClick/unicorn.sock/", host: "107.170.79.150"
2017/05/30 20:42:20 [error] 2135#2135: *51 upstream timed out (110: Connection timed out) while reading response header from upstream, client: 74.109.5.103, server: _, request: "GET / HTTP/1.1", upstream: "http://unix:/run/DigitalOceanOneClick/unicorn.sock/", host: "107.170.79.150"<^>

So all I know is that unicorn is not communicating with nginx. No idea why. This was working fine up until this most recent git pull.

Things I have tried that have not fixed the issue:

service unicorn restart
service nginx reload

restarting my server

gem install bundle
bundle install
bundle update

manually removing the Gemfile.lock file and running bundle install again

rake assets:precompile

in unicorn.conf, Changing the line

listen "unix:/run/DigitalOceanOneClick/unicorn.sock"

to 

listen "/run/DigitalOceanOneClick/unicorn.sock"

manually removing the unicorn.sock file and verifying it is regenerated with a unicorn restart.

What further can I do to troubleshoot this problem? Why did this happen? How can I fix it?

Log In to Comment
1 Answer
hansen May 31, 2017

Hi @jcspampinato

Without knowing a lot about Rails, you need to add some logging in your Unicorn configuration, since it seems like that's where the issue is.
https://stackoverflow.com/questions/41074666/how-to-check-logs-for-rails-application-on-unicorn-and-nginx
http://help.papertrailapp.com/kb/configuration/unicorn/

Also, can you post you Nginx server block - and use the </> in the toolbar of the comment editor to display it as clean code.

Reply
  • jcspampinato May 31, 2017

    Hi @hansen, thanks for your reply.

    I followed the recommendations at your stackoverflow link and changed
    config.considerallrequestslocal to true
    but found that
    config.log    level
    was already set to the recommended
    :debug

    I ran service unicorn restart after making these changes and found still that there was no unicorn.log changes.

    To be perfectly clear, I renamed my existing, not changed for two weeks unicorn.log file to ol.unicorn.log.old, and after restarting unicorn, there is no new unicorn.log being generated. I don't know why.

    Here is my nginx server block:

    server {
    listen   80;
    root /home/rails/popEFX/public;
    server_name _;
    index index.htm index.html;

    location / {
            try_files $uri/index.html $uri.html $uri @app;
    }

    location ~* ^.+\.(jpg|jpeg|gif|png|ico|zip|tgz|gz|rar|bz2|doc|xls|exe|pdf|ppt|txt|tar|mid|midi|wav|bmp|rtf|mp3|flv|mpeg|avi)$ {
                    try_files $uri @app;
            }

     location @app {
            proxy_set_header X-Forwarded-For $proxy_add_x_forwarded_for;
            proxy_set_header Host $http_host;
            proxy_redirect off;
            proxy_pass http://app_server;
    }
}
  • jcspampinato May 31, 2017

    Okay, thought I was getting somewhere.

    I did some hunting around and found the correct log file under myproject/log/unicorn.log. Found this most recent logging there:

    /usr/local/rvm/gems/ruby-2.4.0/bin/ruby_executable_hooks:15:in `eval'
/usr/local/rvm/gems/ruby-2.4.0/bin/ruby_executable_hooks:15:in `<main>'
E, [2017-05-31T13:08:20.783873 #10962] ERROR -- : reaped #<Process::Status: pid 20584 exit 1> worker=0
I, [2017-05-31T13:08:20.784030 #10962]  INFO -- : worker=0 spawning...
I, [2017-05-31T13:08:20.785177 #20587]  INFO -- : worker=0 spawned pid=20587
I, [2017-05-31T13:08:20.785378 #20587]  INFO -- : Refreshing Gem list
E, [2017-05-31T13:08:20.804830 #20587] ERROR -- : Could not find rack-1.6.8 in any of the sources (Bundler::GemNotFound)
/usr/local/rvm/gems/ruby-2.4.0/gems/bundler-1.14.6/lib/bundler/spec_set.rb:87:in `block in materialize'
...

    So I ran 'bundle update rack', verified that rack was listed among the gems, and restarted unicorn and reloaded nginx. I rechecked unicorn.log and found that unicorn still errors out on rack-01.6.8 despite it being listed among my gems on completion of bundle update.

    So I am continuing to figure out what needs doing to prevent this.

  • jcspampinato May 31, 2017

    Third update:

    after running a rake tmp:cache:clear, then bundle update, then bundle install, unicorn is now choking on the Gem

    i18n-0.8.4

    Which is listed among my gems after bundle install. The cache clear, update, install actions don't have any impact on this problem. Unicorn just keeps choking on the gem, crashing, and respawning.

    I also tried 'bundle clean --force' before the cache clear/update/install to no avail.

    unicorn.log:

    /usr/local/rvm/gems/ruby-2.4.0/bin/ruby_executable_hooks:15:in `<main>'
E, [2017-05-31T13:55:43.407427 #4138] ERROR -- : reaped #<Process::Status: pid 17287 exit 1> worker=0
I, [2017-05-31T13:55:43.407677 #4138]  INFO -- : worker=0 spawning...
I, [2017-05-31T13:55:43.409390 #17290]  INFO -- : worker=0 spawned pid=17290
I, [2017-05-31T13:55:43.409704 #17290]  INFO -- : Refreshing Gem list
E, [2017-05-31T13:55:43.451318 #17290] ERROR -- : Could not find i18n-0.8.4 in any of the sources (Bundler::GemNotFound)
/usr/local/rvm/gems/ruby-2.4.0/gems/bundler-1.14.6/lib/bundler/spec_set.rb:87:in `block in materialize'
/usr/local/rvm/gems/ruby-2.4.0/gems/bundler-1.14.6/lib/bundler/spec_set.rb:80:in `map!'
/usr/local/rvm/gems/ruby-2.4.0/gems/bundler-1.14.6/lib/bundler/spec_set.rb:80:in `materialize'
    • hansen May 31, 2017

      @jcspampinato
      Seems like you've come a long way. Did you try to install that specific version if the internationalization gem? You might have another version installed, but your bundle is expecting 0.8.4

      sudo gem install i18n --version 0.8.4
      • jcspampinato May 31, 2017

        I have made progress in identifying the issue, for sure. It was your comment about the logging being absent that gave me the impetus to question my assumption that I was checking the correct log file. Lost a lot of hours operating under that assumption.

        Running that command yields 

        Successfully installed i18n-0.8.4
1 gem installed

        Then restarting unicorn results in the crash respawn cycle, again centered around E, [2017-05-31T21:08:50.847363 #13589] ERROR -- : Could not find i18n-0.8.4 in any of the sources (Bundler::GemNotFound)

        This has confused me all along. 'bundle install' lists the i18n-0.8.4 gem as being installed, yet unicorn acts as if it isn't there. I don't know where it should be, but in my gems path there is a directory for i18n-0.8.1 no matter how many times I un/install i18n-0.8.4, or uninstall all gems, and I don't know enough to understand why this would be or how to correct it. Or if this is or isn't the source of my problem.

        I was advised to attempt gem query --local. Which does not list i18n, and I am trying to ascertain my next steps based on this information.

Have another answer? Share your knowledge.

Related Questions