Need help to fix ERR 500


#21

Last night, I did a diff between openfoodnetwork installed by ansible and the package I get from
github.
Then there is no difference. That’s normal.

As I remember the first install I did was from github, by following the step explained on the
github page, and after some days to find all ruby packages needed. On this install, I was able to create enterprise.

I try to run bundle install on version I got from github, but I get an error message from ruby,
some package are missing. I checked the ruby version and I get ruby 1.8.7.
This version was installed from ansible by running playbook available on ofn_deployment.
The server is running Ubuntu 12.04. I use this version because this is a requirement written on github page.

I upgrade ruby to 1.9.3 and delete the openfoodnetwork directory and the database.
I run again the ansible playbook. When I log on and try to create a new enterprise, I get again ERR 500.

I suppose there is something wrong on the SQL transaction but can’t find what.

Is it possible to get “debug info” from postgresql ?


#22

Good thinking!

$ less /var/log/postgresql/postgresql-9.1-main.log


#23

make that sudo less /var/log/postgresql/postgresql-9.1-main.log and here’s probably the root of our issue:

pg_get_expr(d.adbin, d.adrelid), a.attnotnull, a.atttypid, a.atttypmod
                      FROM pg_attribute a LEFT JOIN pg_attrdef d
                        ON a.attrelid = d.adrelid AND a.attnum = d.adnum
                     WHERE a.attrelid = '"versions"'::regclass
                       AND a.attnum > 0 AND NOT a.attisdropped
                     ORDER BY a.attnum
        
2015-09-18 06:11:48 UTC FATAL:  role "vagrant" does not exist
2015-09-18 06:12:23 UTC FATAL:  role "root" does not exist
2015-09-18 06:12:48 UTC ERROR:  relation "enterprises" does not exist at character 22

We need to add - probably vagrant as a user for postgresql.


#24

Tried this:

vagrant@vagrant-ubuntu-precise-64:~$ sudo -u postgres createuser vagrant
Shall the new role be a superuser? (y/n) y

Still getting errors, but we’re on the right track!

2015-09-18 05:04:40 UTC LOG:  database system was shut down at 2015-09-18 05:04:39 UTC
2015-09-18 05:04:40 UTC LOG:  database system is ready to accept connections
2015-09-18 05:04:40 UTC LOG:  autovacuum launcher started
2015-09-18 05:04:40 UTC LOG:  incomplete startup packet
2015-09-18 05:05:03 UTC FATAL:  database "openfoodnetwork" does not exist
2015-09-18 05:16:24 UTC FATAL:  database "openfoodnetwork" does not exist
2015-09-18 05:16:24 UTC FATAL:  database "openfoodnetwork" does not exist
2015-09-18 05:16:42 UTC FATAL:  database "openfoodnetwork" does not exist
2015-09-18 05:17:02 UTC ERROR:  relation "spree_preferences" does not exist at character 315
2015-09-18 05:17:02 UTC STATEMENT:              SELECT a.attname, format_type(a.atttypid, a.atttypmod),
                             pg_get_expr(d.adbin, d.adrelid), a.attnotnull, a.atttypid, a.atttypmod
                      FROM pg_attribute a LEFT JOIN pg_attrdef d
                        ON a.attrelid = d.adrelid AND a.attnum = d.adnum
                     WHERE a.attrelid = '"spree_preferences"'::regclass
                       AND a.attnum > 0 AND NOT a.attisdropped
                     ORDER BY a.attnum
        
2015-09-18 05:17:03 UTC ERROR:  relation "versions" does not exist at character 315
2015-09-18 05:17:03 UTC STATEMENT:              SELECT a.attname, format_type(a.atttypid, a.atttypmod),
                             pg_get_expr(d.adbin, d.adrelid), a.attnotnull, a.atttypid, a.atttypmod
                      FROM pg_attribute a LEFT JOIN pg_attrdef d
                        ON a.attrelid = d.adrelid AND a.attnum = d.adnum
                     WHERE a.attrelid = '"versions"'::regclass
                       AND a.attnum > 0 AND NOT a.attisdropped
                     ORDER BY a.attnum
        
2015-09-18 06:11:48 UTC FATAL:  role "vagrant" does not exist
2015-09-18 06:12:23 UTC FATAL:  role "root" does not exist
2015-09-18 06:12:48 UTC ERROR:  relation "enterprises" does not exist at character 22
2015-09-18 06:12:48 UTC STATEMENT:  SELECT 1 AS one FROM "enterprises" WHERE "enterprises"."permalink" = 'my-enterprise' LIMIT 1;
2015-09-18 06:22:08 UTC ERROR:  syntax error at or near "select" at character 24
2015-09-18 06:22:08 UTC STATEMENT:  select openfoodnetwork
        select postgres
        select me
        SELECT 1 AS one FROM "enterprises" WHERE "enterprises"."permalink" = 'my-enterprise' LIMIT 1;



#25

Was having authentication issues using su -. Solution:

su asks for the root password. Since ubuntu doesn’t use a root account, you normally do not have this password set.

To become root use sudo su with your personal password in this case “vagrant”.

Now we can try to create postgres users and add to db:

$ su - postgres
# psql openfoodnetwork
openfoodnetwork=# CREATE USER vagrant WITH PASSWORD 'vagrant';
ERROR:  role "vagrant" already exists
openfoodnetwork=# GRANT ALL PRIVILEGES ON DATABASE openfoodnetwork to vagrant;
GRANT
openfoodnetwork=# 

#26

I don’t have any log on the postgresql-9.1-main.log when I get ERR 500
On this log file, I just have some log writtent during the installation process.


#27

I actually deleted (and recreated) my log/test.log and now it’s not being written to. permissions 644, as are the other log files. Harumph!


#28

Try to change to 664, on my server, all log files have 664 permissions. Maybe postgresql write on it.


#29

Sorry I’ve dropped the ball on this one - I’ve had to pull back a little on OFN due to a bunch of other commitments. Sounds like the Aussies are going to invest some time here so hopefully will resolve the issues.


#30

Hi all,

I’m back from travels and just getting back in touch with everything OFN. Sorry that it hasn’t been smooth sailing!

When tracking down 500 errors, it’s hard to do anything without knowing what the error and backtrace is, and unfortunately the Rails logs outside the development environment don’t reveal enough information. The easiest solution is to use an error capture service, and we have Bugsnag set up for that purpose, which is a tool for capturing those errors and reporting them in a web interface.

It’s a paid service, but very cheap with few limits on usage. So it’s no problem for me to set anyone up with access who needs it. @gnollet and anyone else who’d like access, could you send me a private message with your email address? I’ll create an OFN France project on Bugsnag, add you to it and send you some setup instructions.

I’ll take this into consideration for the overall provisioning process, too. I’m thinking that we should build the bugsnag setup into that process. Otherwise diagnosing this sort of error is like trying to find a needle in a haystack in a dark room without a torch (or a magnet).


#31

Hi,
Thanks @RohanM to send me the bugsnag key.
But, maybe I’m a pain, but I can’t register the server.

I did rake bugsnag:test_exception to follow information on bugsnag webpage but nothing happen.
Then I try follow integration procedure but I get an error when I ran rails generate bugsnag ‘bugsnagkey’ :
/home/openfood/.rbenv/versions/1.9.3-p392/lib/ruby/1.9.1/rubygems/custom_require.rb:36:in require': cannot load such file -- active_support (LoadError) from /home/openfood/.rbenv/versions/1.9.3-p392/lib/ruby/1.9.1/rubygems/custom_require.rb:36:inrequire’
from /usr/lib/ruby/vendor_ruby/railties/lib/rails_generator.rb:30:in <top (required)>' from /home/openfood/.rbenv/versions/1.9.3-p392/lib/ruby/1.9.1/rubygems/custom_require.rb:36:inrequire’
from /home/openfood/.rbenv/versions/1.9.3-p392/lib/ruby/1.9.1/rubygems/custom_require.rb:36:in require' from /usr/lib/ruby/vendor_ruby/railties/bin/rails:16:in

Then, I drop my intallation and restart a new fresh. I insert bugsnag key on vars.yml. Installation was done sucessfully, not error identified. Then I tried to create an enterprise and got ERR 500. on the test.log file I get the same message :
Completed 500 Internal Server Error in 519.5ms
** [Bugsnag] No API key configured, couldn’t notify

I retry to install the key with rails generate bugsnag … and get the same error message then upper


#32

Hmm, could you have a look on the server in config/initializers/bugsnag.rb? Ours looks like:

Bugsnag.configure do |config|
  config.api_key = "xyzzy"
  config.notify_release_stages = %w(production staging)
  config.use_ssl = true
end

This is what vars.yml and rails generate bugsnag should be setting up. Is that information there?


#33

Redeployed and it is being written to now - with 664 permissions. Thanks for the tip.


#34

Hi,
I find the bugsnag.rb file on openfoodnetwork/current/config
The content is like you show it.
should I move this file un config/initializers ?

My envirronement is test, is there something to update in the file ?

Thanks


#35

i messaged you, as I’m sure you’ll see. : )


#36

Hi, Tonight, I tried to install openfoodnetwork package from github without ansible, then the application is running in port 3000. I can create an enterprise.
Only the email problem still exist.
Then there is something wrong on the ansible playbook which is not setup but I don’t know what


#37

Interesting to hear that it’s working when set up without ansible. If it’s running on port 3000, then it sounds like it’s running the development web server, which is not suitable for the public to use.

Have you had any luck configuring bugsnag? I noticed yesterday that ansible puts the configuration file in the wrong place by default. It should be located at config/initializers/bugsnag.rb. Could you check that that’s set up correctly and give it another shot with unicorn/nginx? Hopefully that’ll log the error to bugsnag and we’ll be able to debug it from there.

Cheers,
Rohan


#38

Okay. I’m futzing around with bugsnag now. Tried running bundle exec rails generate bugsnag my_key but getting “Could not find generator bugsnag”. I’ll track down to bugsnag.rb file and put it in the right place…

it’s in ./config/bugsnag.rb

moved:

vagrant@vagrant-ubuntu-precise-64:~/apps/pcolacoop/current$ cat config/initializers/bugsnag.rb 
Bugsnag.configure do |config|
  config.api_key = "my_key"
  config.notify_release_stages = %w(production staging)
  config.use_ssl = true
end


Still getting:

vagrant@vagrant-ubuntu-precise-64:~/apps/pcolacoop/current$ tail -10 log/test.log 
   (0.2ms)  SELECT COUNT(*) FROM "spree_states" WHERE "spree_states"."country_id" = 49 AND (name = 'Alabama' OR abbr = 'Alabama')
  Spree::State Load (0.2ms)  SELECT "spree_states".* FROM "spree_states" WHERE "spree_states"."country_id" = 49 AND (name = 'Alabama' OR abbr = 'Alabama') ORDER BY name ASC LIMIT 1
   (0.2ms)  SELECT COUNT(*) FROM "enterprises" WHERE "enterprises"."name" = ''
  CACHE (0.0ms)  SELECT "spree_countries".* FROM "spree_countries" WHERE "spree_countries"."id" = 49 LIMIT 1
  CACHE (0.0ms)  SELECT COUNT(*) FROM "spree_states" WHERE "spree_states"."country_id" = 49 AND (name = 'Alabama' OR abbr = 'Alabama')
  CACHE (0.0ms)  SELECT "spree_states".* FROM "spree_states" WHERE "spree_states"."country_id" = 49 AND (name = 'Alabama' OR abbr = 'Alabama') ORDER BY name ASC LIMIT 1
  Enterprise Exists (0.2ms)  SELECT 1 AS one FROM "enterprises" WHERE "enterprises"."permalink" = 'my-enterprise' LIMIT 1
   (0.2ms)  ROLLBACK
Completed 500 Internal Server Error in 264.9ms
** [Bugsnag] No API key configured, couldn't notify
vagrant@vagrant-ubuntu-precise-64:~/apps/pcolacoop/current$ ls -l log/
total 396
-rw-rw-r-- 1 vagrant vagrant     66 Sep 25 02:28 delayed_job.log
-rw-rw-r-- 1 vagrant vagrant 133791 Sep 25 03:14 development.log
-rw-rw-r-- 1 vagrant vagrant  50248 Sep 25 03:14 newrelic_agent.log
-rw-rw-r-- 1 vagrant vagrant 203326 Sep 25 03:15 test.log
vagrant@vagrant-ubuntu-precise-64:~/apps/pcolacoop/current$ date
Fri Sep 25 03:16:44 UTC 2015

Changed the bugsnag content:

Bugsnag.configure do |config|
  config.api_key = "the_key_again"
  config.notify_release_stages = %w(production staging development)
  config.use_ssl = false
end

Restarting Rails server again…

Same. Vagrant Reload…


#39

Also had wrong permissions on bugsnag file (775 or something):

chmod 664 config/initializers/bugsnag.rb 

We;re getting somewhere!

  Enterprise Exists (0.2ms)  SELECT 1 AS one FROM "enterprises" WHERE "enterprises"."permalink" = 'my-enterprise' LIMIT 1
   (0.1ms)  ROLLBACK
Completed 500 Internal Server Error in 501.0ms

#40

Well. This logged an error in bugsnag: $ rake bugsnag:test_exception, But the 500 error doesn’t seem to have.