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