OFN Again – Back to OpenFoodNetwork install with new Vigor

So we finally have a server and a team for OFN US instance.

I Git rebased the latest updates to master ofn_deployment repository on top of my fork.

First I had forgotten to install Ansible dependencies: ansible-galaxy install -r install_roles.yml

There was a little misspelling needed fixing, i10n_repo was l10n_repo.

Now having an error on RUNNING HANDLER [mortik.nginx-rails : restart nginx]:

emerg duplicate upstream "unicorn"

SSH’d into the server and sudo tail -1 /var/log/nginx/error.log:

2016/05/01 14:22:41 [emerg] 3893#0: duplicate upstream "unicorn" in /etc/nginx/sites-enabled/ofn_america:1

Let’s look at that file:

    upstream unicorn {
        server unix:/home/ubuntu/apps/ofn_america/shared/sock/unicorn.ofn_america.sock fail_timeout=0;
    }

    server {
        listen 80;
        server_name  www.staging.usfoodcoop.org staging.usfoodcoop.org;
        rewrite ^/(.*) https://staging.usfoodcoop.org/$1 permanent;
    }

    server {
        listen 443;

        include ofn_america_ssl;

        server_name www.staging.usfoodcoop.org;
        rewrite ^(.*) https://staging.usfoodcoop.org/$1 permanent;
    }

    #etc...

OK. Those are the variables for our staging server, and I’m back to the local Vagrant/VirtualBox/Dev install. They may have been installed when I had accidentally been referencing the staging variables doc earlier. Let’s try and re-provision. Ah. The staging.vars.yml file was still being referenced in provision.yml.

Now that we’re calling the correct file, we’re getting:

server {
    listen 80;
    server_name  www.127.0.0.1;
    rewrite ^/(.*) http://127.0.0.1/$1 permanent;
}

Need to figure out proper syntax for /roles/webserver/templates/nginx_unicorn.j2:

{% if domain == '127.0.0.1' %}
    sub_directory ''
{% else %}
    sub_directory 'www.'
{% endif %}
{% if protocol == 'https' %}
    server_name  {{sub_directory}} {{ domain }} {{ domain }};
{% else %}

This seems to work:

{% if domain == '127.0.0.1' or domain == 'localhost'%}
    {% set sub_directory = '' -%}
{% else %}
    {% set sub_directory = 'www.' -%}
{% endif %}

OK. Progress. I think.

emerg unknown directive \"Unicorn\

Re-provisioned and working this time. Sweet. 74 tasks completed.

apps/ofn_america/current directory: bundle exec rails server -b 0.0.0.0 but no page on front end at http://127.0.0.1:3000/.

Hmmm.

wget 127.0.0.1:3000
--2016-05-01 13:57:01--  http://127.0.0.1:3000/
Connecting to 127.0.0.1:3000... failed: Connection refused.

Rrrrr.

sudo tail -1 /var/log/nginx/error.log
2016/05/01 18:17:54 [warn] 4053#0: conflicting server name "127.0.0.1" on 0.0.0.0:80, ignored

But I don’t think that’s relevant. I may have seen this issue before. Unicorn?

There’s supposed to be a unicorn log file above the current directory in shared/log/unicorn.log.

Not there.

sudo service unicorn_ofn_america start

No output. No difference.

Did notice the file in shared, l10n and realized I was wrong with thinking it was a misspelling. I know what l10n is! At any rate, it deployed, completing like 72 tasks. But same “Connection refused” issue.

Wait… We’re not

$ ls -l /etc/init.d | grep unicorn
-rwxr--r-- 1 vagrant vagrant 1896 May  1 20:07 unicorn_ofn_america

What is this:

$ cat /etc/monit/conf.d/ofn_america

It’s this:
check process ofn_america_dj_worker_0
with pidfile /home/vagrant/apps/ofn_america/current/tmp/pids/delayed_job.0.pid
start program = “/bin/bash -c ‘RAILS_ENV=development /home/vagrant/.rbenv/shims/ruby /home/vagrant/apps/ofn_america/current/script/delayed_job -i 0 start'”
as uid vagrant and gid vagrant
with timeout 120 seconds
stop program = “/bin/bash -c ‘RAILS_ENV=development /home/vagrant/.rbenv/shims/ruby /home/vagrant/apps/ofn_america/current/script/delayed_job -i 0 stop'”
as uid vagrant and gid vagrant
with timeout 120 seconds
if mem is greater than 250.0 MB for 3 cycles then restart

So let’s start is manually:

$ /bin/bash -c 'RAILS_ENV=development /home/vagrant/.rbenv/shims/ruby /home/vagrant/apps/ofn_america/current/script/delayed_job -i 0 start'

And:

(eval):1: warning: encountered \r in middle of line, treated as a mere space

delayed_job.0: process with pid 6987 started.

Which matches the process ID in: shared/pids/unicorn.pid?

$ cat shared/pids/unicorn.pid
6521

No.

$ /bin/bash -c 'RAILS_ENV=development /home/vagrant/.rbenv/shims/ruby /home/vagrant/apps/ofn_america/current/script/delayed_job -i 0 status'
(eval):1: warning: encountered \r in middle of line, treated as a mere space

delayed_job.0: running [pid 6987]

Delayed job issues again. Vague recollections.

I think there was in issue with this file:

roles/common/templates/monit.j2

I had changed the first line check process openfoodnetwork_dj_worker_0 to match our App name: check process ofn_america_dj_worker_0. But that’s what the file I’m deploying from now looks like.

sudo service monit restart
 * Stopping daemon monitor monit                                         [ OK ] 
 * Starting daemon monitor monit                                         [ OK ]    

Still no luck in front end.

Let’s try running the delayed job manually:

$ /bin/bash -c 'RAILS_ENV=/home/vagrant/.rbenv/shims/ruby /home/vagrant/apps/ofn_america/current/script/delayed_job -i 0 start'

Yum:

You did not specify how you would like Rails to report deprecation notices for your development/home/vagrant/.rbenv/shims/ruby environment, please set config.active_support.deprecation to :log, :notify or :stderr at config/environments/development/home/vagrant/.rbenv/shims/ruby.rb
/home/vagrant/.gem/ruby/2.1.0/gems/activerecord-3.2.21/lib/active_record/connection_adapters/abstract/connection_specification.rb:47:in `resolve_hash_connection': database configuration does not specify adapter (ActiveRecord::AdapterNotSpecified)
    from /home/vagrant/.gem/ruby/2.1.0/gems/activerecord-3.2.21/lib/active_record/connection_adapters/abstract/connection_specification.rb:41:in `resolve_string_connection'
    from /home/vagrant/.gem/ruby/2.1.0/gems/activerecord-3.2.21/lib/active_record/connection_adapters/abstract/connection_specification.rb:25:in `spec'
    from /home/vagrant/.gem/ruby/2.1.0/gems/activerecord-3.2.21/lib/active_record/connection_adapters/abstract/connection_specification.rb:130:in `establish_connection'
    from /home/vagrant/.gem/ruby/2.1.0/gems/activerecord-3.2.21/lib/active_record/railtie.rb:88:in `block (2 levels) in <class:Railtie>'
    from /home/vagrant/.gem/ruby/2.1.0/gems/activesupport-3.2.21/lib/active_support/lazy_load_hooks.rb:36:in `instance_eval'
    from /home/vagrant/.gem/ruby/2.1.0/gems/activesupport-3.2.21/lib/active_support/lazy_load_hooks.rb:36:in `execute_hook'
    from /home/vagrant/.gem/ruby/2.1.0/gems/activesupport-3.2.21/lib/active_support/lazy_load_hooks.rb:26:in `block in on_load'
    from /home/vagrant/.gem/ruby/2.1.0/gems/activesupport-3.2.21/lib/active_support/lazy_load_hooks.rb:25:in `each'
    from /home/vagrant/.gem/ruby/2.1.0/gems/activesupport-3.2.21/lib/active_support/lazy_load_hooks.rb:25:in `on_load'
    from /home/vagrant/.gem/ruby/2.1.0/gems/activerecord-3.2.21/lib/active_record/railtie.rb:80:in `block in <class:Railtie>'
    from /home/vagrant/.gem/ruby/2.1.0/gems/railties-3.2.21/lib/rails/initializable.rb:30:in `instance_exec'
    from /home/vagrant/.gem/ruby/2.1.0/gems/railties-3.2.21/lib/rails/initializable.rb:30:in `run'
    from /home/vagrant/.gem/ruby/2.1.0/gems/railties-3.2.21/lib/rails/initializable.rb:55:in `block in run_initializers'
    from /home/vagrant/.gem/ruby/2.1.0/gems/railties-3.2.21/lib/rails/initializable.rb:54:in `each'
    from /home/vagrant/.gem/ruby/2.1.0/gems/railties-3.2.21/lib/rails/initializable.rb:54:in `run_initializers'
    from /home/vagrant/.gem/ruby/2.1.0/gems/railties-3.2.21/lib/rails/application.rb:136:in `initialize!'
    from /home/vagrant/.gem/ruby/2.1.0/gems/railties-3.2.21/lib/rails/railtie/configurable.rb:30:in `method_missing'
    from /home/vagrant/apps/ofn_america/current/config/environment.rb:5:in `<top (required)>'
    from /home/vagrant/.rbenv/versions/2.1.5/lib/ruby/2.1.0/rubygems/core_ext/kernel_require.rb:55:in `require'
    from /home/vagrant/.rbenv/versions/2.1.5/lib/ruby/2.1.0/rubygems/core_ext/kernel_require.rb:55:in `require'
    from /home/vagrant/apps/ofn_america/current/script/delayed_job:3:in `<main>'

In the first line, what is config/environments/development/home/vagrant/.rbenv/shims/ruby.rb all about? This exists: /home/vagrant/.rbenv/shims/ruby.rb. And this: apps/ofn_america/current/config/environments/development.rb. Ah, it’s the RAILS_ENV variable I’m setting in the command above.

Here we go:

$ /bin/bash -c 'RAILS_ENV="development" /home/vagrant/apps/ofn_america/current/script/delayed_job -i 0 start'
(eval):1: warning: encountered \r in middle of line, treated as a mere space
delayed_job.0: process with pid 6472 started.

Log file locations:

apps/ofn_america/shared/log/newrelic_agent.log  # not using currently, using bugsnag
apps/ofn_america/shared/log/unicorn.log
apps/ofn_america/current/log/
    delayed_job.log  
    development/ 
    development.log  
    home/
    newrelic_agent.log
/var/log/ # many many log files and dirs
/var/log/postgresql/
/var/log/nginx/
/var/log/monit.log
/home/vagrant/log/

Let’s poke around.

$ tail -10 apps/ofn_america/shared/log/unicorn.log 
(eval):1: warning: encountered \r in middle of line, treated as a mere space
I, [2016-05-02T06:06:01.495200 #6839]  INFO -- : worker=1 ready
I, [2016-05-02T06:06:01.547540 #6837]  INFO -- : worker=0 ready
bundler: failed to load command: unicorn (/home/vagrant/.gem/ruby/2.1.0/bin/unicorn)
ArgumentError: Already running on PID:6834 (or pid=/home/vagrant/apps/ofn_america/shared/pids/unicorn.pid is stale)
/home/vagrant/.gem/ruby/2.1.0/gems/unicorn-4.9.0/lib/unicorn/http_server.rb:206:in `pid='
/home/vagrant/.gem/ruby/2.1.0/gems/unicorn-4.9.0/lib/unicorn/http_server.rb:135:in `start'
/home/vagrant/.gem/ruby/2.1.0/gems/unicorn-4.9.0/bin/unicorn:126:in `<top (required)>'
/home/vagrant/.gem/ruby/2.1.0/bin/unicorn:23:in `load'
/home/vagrant/.gem/ruby/2.1.0/bin/unicorn:23:in `<top (required)>'

Nginx?

$ tail -10 /var/log/nginx/error.log
2016/05/02 01:17:23 [warn] 3977#0: conflicting server name "127.0.0.1" on 0.0.0.0:80, ignored

Monit:

$ sudo tail -10 /var/log/monit.log 
[UTC May  2 05:50:27] error    : 'ofn_america_dj_worker_0' failed to start
[UTC May  2 05:52:27] error    : 'ofn_america_dj_worker_0' process is not running
[UTC May  2 05:52:27] info     : 'ofn_america_dj_worker_0' trying to restart
[UTC May  2 05:52:27] info     : 'ofn_america_dj_worker_0' start: /bin/bash
[UTC May  2 05:54:27] error    : 'ofn_america_dj_worker_0' failed to start
[UTC May  2 05:56:27] error    : 'ofn_america_dj_worker_0' process is not running
[UTC May  2 05:56:27] info     : 'ofn_america_dj_worker_0' trying to restart
[UTC May  2 05:56:27] info     : 'ofn_america_dj_worker_0' start: /bin/bash
[UTC May  2 05:56:42] info     : 'ofn_america_dj_worker_0' started
[UTC May  2 05:58:42] info     : 'ofn_america_dj_worker_0' process is running with pid 6472

Delayed Job:

$ tail -10 delayed_job.log 
# Logfile created on 2016-05-02 01:18:21 +0000 by logger.rb/44203
2016-05-02T05:56:42+0000: [Worker(delayed_job.0 host:vagrant-ubuntu-precise-64 pid:6472)] Starting job worker

Development:

$ tail -1 development.log 
Delayed::Backend::ActiveRecord::Job Load (0.8ms)  UPDATE "delayed_jobs" SET locked_at = '2016-05-02 06:34:29.211629', locked_by = 'delayed_job.0 host:vagrant-ubuntu-precise-64 pid:6472' WHERE id IN (SELECT id FROM "delayed_jobs" WHERE ((run_at <= '2016-05-02 06:34:29.210760' AND (locked_at IS NULL OR locked_at < '2016-05-02 06:19:29.210796') OR locked_by = 'delayed_job.0 host:vagrant-ubuntu-precise-64 pid:6472') AND failed_at IS NULL) ORDER BY priority ASC, run_at ASC LIMIT 1 FOR UPDATE) RETURNING *

The issue may be unrelated to Nginx, Monit, Delayed Job, Unicorn and simply a Rails or Vagrant configuration issue.

Some Configuration file locations:

ofn_deployment/templates/nginx.conf.j2
ofn_deployment/roles/webserver/templates/nginx_unicorn.j2

What other log files might we want to poke around into:

$ find / -name "*.log"
long list....

Nothing that seems terribly relevant at the moment. Checked my local /private/etc/hosts file and commented out line 127.0.0.1 localhost, which is making no difference.

This might be relevant: https://www.ruby-forum.com/topic/315079

Asked on SO:

The Rails application is running on port 3000:

$ bundle exec rails server -b 0.0.0.0
=> Booting Unicorn
=> Rails 3.2.21 application starting in development on http://0.0.0.0:3000
=> Call with -d to detach
=> Ctrl-C to shutdown server
(eval):1: warning: encountered \r in middle of line, treated as a mere space
listening on addr=0.0.0.0:3000 fd=14
worker=0 spawning...
master process ready
worker=0 spawned pid=5811
worker=0 ready

Website is available on the Virtual Machine:

$ wget 127.0.0.1:3000
--2016-05-05 05:15:54--  http://127.0.0.1:3000/
Connecting to 127.0.0.1:3000... connected.
HTTP request sent, awaiting response... 200 OK
Length: unspecified [text/html]
Saving to: `index.html'

        [ <=>                                   ] 42,036        --.-K/s   in 0s      

2016-05-05 05:15:55 (222 MB/s) - `index.html' saved [42036]

But from the host machine:

$ wget http://127.0.0.1:3000/
--2016-05-05 00:07:02--  http://127.0.0.1:3000/
Connecting to 127.0.0.1:3000... failed: Connection refused.

Port Scanning host: 127.0.0.1:

 Open TCP Port:     21          ftp
 Open TCP Port:     22          ssh
 Open TCP Port:     80          http
 Open TCP Port:     88          kerberos
 Open TCP Port:     111         sunrpc
 Open TCP Port:     445         microsoft-ds
 Open TCP Port:     548         afpovertcp
 Open TCP Port:     631         ipp
 Open TCP Port:     965
 Open TCP Port:     975
 Open TCP Port:     1015
 Open TCP Port:     1019
 Open TCP Port:     2049        nfsd
 Open TCP Port:     2200        ici
 Open TCP Port:     2222        rockwell-csp2
 Open TCP Port:     3300
 Open TCP Port:     5432        postgresql
 Open TCP Port:     8080        http-alt

This is the basic contents of /private/etc/hosts:

127.0.0.1   localhost
127.0.0.1   test.localhost

255.255.255.255 broadcasthost
::1             localhost 
fe80::1%lo0 localhost

192.168.33.102  vagrant  # VAGRANT: c460068dd8a5a09607cfd3402843d82a (local) / 0668df93-b211-421f-86db-bb2ff8e57175
192.168.44.44  vdd.dev  # VAGRANT: 07e9613958e0db441d6b9af1328fa214 (default) / 4d655cd6-bf5a-442a-8093-4ac431b7d890

The nginx/error.log is just confirming the refused connection and Unicorn log equally uninformative as far as I can tell.

This is contents of /etc/nginx/sites-available/my_application:

upstream unicorn {
  server unix:/home/vagrant/apps/ofn_america/shared/sock/unicorn.ofn_america.sock fail_timeout=1;
}


server {
  listen 80;
  server_name   127.0.0.1;
  rewrite ^/(.*) http://127.0.0.1/$1 permanent;
}


server {
  listen 80;
  server_name 127.0.0.1;
  root /home/vagrant/apps/ofn_america/current/public;


  try_files $uri/index.html $uri @unicorn;
  location @unicorn {
    proxy_set_header X-Forwarded-For $proxy_add_x_forwarded_for;
    proxy_set_header Host $host;
    proxy_set_header X-Forwarded-Proto $scheme;
    proxy_redirect off;
    proxy_pass http://unicorn;
  }

  location ~ ^/(assets)/ {
    gzip_static on;
    expires max;
    add_header Cache-Control public;
    #add_header Last-Modified "";
    #add_header ETag "";
  }
  error_page 500 502 503 504 /500.html;
  client_max_body_size 4G;
  keepalive_timeout 60;
}

Solution is that ofn_deployment is set (ofn_deployment/Vagrantfile) to have vagrant/VM available on the host machine at http://127.0.0.1:8080, not http://127.0.0.1:3000.

see https://www.vagrantup.com/docs/networking/forwarded_ports.html