Need help to fix ERR 500

I can confirm that the error also occurs when Spree is seeded with the AU data.

@pmackay @Aidan - could you guys please check if this is a problem you had in UK and how you resolved it? Thanks!

Hi,

Di you knwo how we could get a trace or error message even if bugsnag is not configured ?

** [Bugsnag] No API key configured, couldn’t notify

Thanks

Can you please check if /var/log/nginx/error.log shows anything useful?

I also want to know from Rohan how Bugsnag can be configured or disabled, but it wont be related to any other issue.

I’ve had success configuring the mail settings using Mandrill

Domain / Mail host: smtp.mandrillapp.com
port: 587
conn type: SSL
auth type: login

I cannot immediately think of what could cause the initial error.

I have nothing in error.log

Below, the access.log when creating en enterprise :
193.164.156.11 - - [08/Sep/2015:08:45:24 +0000] “GET /admin/general_settings/edit HTTP/1.1” 200 7106 “http://testfrofn.cloudapp.net/admin” "Mozilla/5.0 (Windows NT 6.1; WOW64; rv:40.0) Gecko/20100101 Firefox/40.0"
193.164.156.11 - - [08/Sep/2015:08:45:26 +0000] “GET /admin/enterprises HTTP/1.1” 200 2881 “http://testfrofn.cloudapp.net/admin/general_settings/edit” "Mozilla/5.0 (Windows NT 6.1; WOW64; rv:40.0) Gecko/20100101 Firefox/40.0"
193.164.156.11 - - [08/Sep/2015:08:45:28 +0000] “GET /admin/enterprises/new HTTP/1.1” 200 7399 “http://testfrofn.cloudapp.net/admin/enterprises” "Mozilla/5.0 (Windows NT 6.1; WOW64; rv:40.0) Gecko/20100101 Firefox/40.0"
193.164.156.11 - - [08/Sep/2015:08:45:32 +0000] “GET /admin/search/known_users?q= HTTP/1.1” 304 0 “http://testfrofn.cloudapp.net/admin/enterprises/new” "Mozilla/5.0 (Windows NT 6.1; WOW64; rv:40.0) Gecko/20100101 Firefox/40.0"
193.164.156.11 - - [08/Sep/2015:08:46:30 +0000] “POST /admin/enterprises HTTP/1.1” 500 5 “http://testfrofn.cloudapp.net/admin/enterprises/new” "Mozilla/5.0 (Windows NT 6.1; WOW64; rv:40.0) Gecko/20100101 Firefox/40.0"
193.164.156.11 - - [08/Sep/2015:08:46:30 +0000] “POST /admin/enterprises HTTP/1.1” 500 5 “http://testfrofn.cloudapp.net/admin/enterprises/new” “Mozilla/5.0 (Windows NT 6.1; WOW64; rv:40.0) Gecko/20100101 Firefox/40.0”

Regarding email issue, when I try to generate a test email, then I see the email is generated on the current/log/test.log file but the email is not sent. I tried to send to local postfix server or sendgrid server, it’s the same thing, nothing is sent

Is there any cache of the configuration ?

Is there any more useful info in the test log? Could you send me a copy of the file?

yes I can, if you want to have access to the server, it’s possible, I can provide you ssh access.

I’m new to Rails (and Ruby) and going through RailsTutorial. Occured to me this morning that I didn’t remember running bundle install. I was able to run it on the VirtualBox and it installed over 200 packages, many of which are Spree packages. So that may have something to do with the issue.

@pmackay, Did you find something to fix our problem ?
Do you think we should try to update to last new version ? (1.1)

Hi,

Have you set this up as a test environment (hence the test.log)? Do you plan to use staging or production later? Can you share your vars.yml file? (remove any sensitive password stuff, etc)

Is there any more content in the log?

paul

That’s a question I have outstanding for Rohan :slight_smile:

Will try to look at other issue later today…

That might be handy.

@pmackay, below the content of vars.yml :
country_code: FR
locale: fr
language: en_AU.UTF-8
timezone: Paris
i10n_repo: https://github.com/openfoodfoundation/i10n_fr.git

currency: EUR
checkout_zone: France

language_packages:

  • language-pack-en-base

domain: testfrofn.cloudapp.net

rails_env: test
protocol: http

git_repo: https://github.com/openfoodfoundation/openfoodnetwork.git
version: HEAD # Tag, branch, commit reference or HEAD

Other parameters are as default or contains sensitives informations (login/pass)

This is a test environement, then when this environement will be OK, we will create a new installation on other server to use it in production.

On the test.log, I find these lines :
Started GET “/admin/search/known_users?q=” for 193.164.156.11 at 2015-09-08 08:45:31 +0000
Processing by Spree::Admin::SearchController#known_users as /

Deface: 10 overrides found for 'spree/layouts/admin’
Deface: ‘promo_admin_tabs’ matched 1 times with '[data-hook=‘admin_tabs’], #admin_tabs[data-hook]'
Deface: [ERROR] The original source for ‘promo_admin_tabs’ has changed, this override should be reviewed to ensure it’s still valid.
Deface: ‘user_admin_tabs’ matched 1 times with '[data-hook=‘admin_tabs’], #admin_tabs[data-hook]'
Deface: [ERROR] The original source for ‘user_admin_tabs’ has changed, this override should be reviewed to ensure it’s still valid.
Deface: ‘auth_admin_login_navigation_bar’ matched 1 times with '[data-hook=‘admin_login_navigation_bar’], #admin_login_navigation_bar[data-hook]'
Deface: [ERROR] The original source for ‘auth_admin_login_navigation_bar’ has changed, this override should be reviewed to ensure it’s still valid.
Deface: ‘set_auth_token_in_backend’ matched 1 times with '[data-hook=‘admin_inside_head’]'
Deface: [ERROR] The original source for ‘set_auth_token_in_backend’ has changed, this override should be reviewed to ensure it’s still valid.
Deface: ‘add_order_cycles_admin_tab’ matched 1 times with '[data-hook=‘admin_tabs’], #admin_tabs[data-hook]'
Deface: [WARNING] No :original defined for ‘add_order_cycles_admin_tab’, you should change its definition to include:
:original => '9045f73f615ba998bd83b39e7a0b1326a4851339’
Deface: ‘admin_inside_head’ matched 1 times with '[data-hook=“admin_inside_head”]'
Deface: [WARNING] No :original defined for ‘admin_inside_head’, you should change its definition to include:
:original => 'b4a64f8d073487295d9088d1f042d21de5c51d2d’
Deface: ‘add_trial_progress_bar’ matched 1 times with '[data-hook=‘admin_footer_scripts’]'
Deface: [WARNING] No :original defined for ‘add_trial_progress_bar’, you should change its definition to include:
:original => 'a417a94b2ad73876600ce71da17874dab70a7335’
Deface: ‘add_enterprises_admin_tab’ matched 1 times with '[data-hook=‘admin_tabs’], #admin_tabs[data-hook]'
Deface: [WARNING] No :original defined for ‘add_enterprises_admin_tab’, you should change its definition to include:
:original => '37217e2635f57eed3bd2394752d8559419c6b751’
Deface: ‘add_groups_admin_tab’ matched 1 times with '[data-hook=‘admin_tabs’], #admin_tabs[data-hook]'
Deface: [WARNING] No :original defined for ‘add_groups_admin_tab’, you should change its definition to include:
:original => '2313218a70e552648d74b04f9a190e863df0df7a’
Deface: ‘add_analytics’ matched 1 times with '[data-hook=‘admin_footer_scripts’]'
Deface: [WARNING] No :original defined for ‘add_analytics’, you should change its definition to include:
:original => '61a2973f09328af6f7fc38daabb57671b9c42b7e’
Spree::User Load (1.6ms) SELECT “spree_users”.* FROM “spree_users” LEFT OUTER JOIN “spree_addresses” ON “spree_addresses”.“id” = “spree_users”.“ship_address_id” LEFT OUTER JOIN “spree_addresses” "bill_addresses_spree_users"
ON “bill_addresses_spree_users”.“id” = “spree_users”.“bill_address_id” LIMIT 10
Rendered /home/openfood/.gem/ruby/1.9.1/bundler/gems/spree-afcc23e489eb/core/app/views/spree/admin/search/users.rabl (4.8ms)
Completed 200 OK in 623.0ms (Views: 395.6ms | ActiveRecord: 10.0ms)
Started POST “/admin/enterprises” for 193.164.156.12 at 2015-09-11 12:02:56 +0000

Maybe these information will help you to locate the issue ?

Thanks

Hi,

I try to create a new server with last version from github, I used i10n_fr where I create state.yml which I think this file was missing for France.
Ansible playbook was running successfull, I just copy seeds files from i10n directory to shared/config directory.
Frontend looks ok, then I log on backend and try to create an enterprise.
Then I get the same ERR 500 message.
The email function is not working also.

Then if you have an idea about these problems, you are welcome.

Thanks

If it of any use, this is test.log on my install. Seems to be occurring on rollback?

$ tail -50 log/test.log 
  Rendered /home/vagrant/.gem/ruby/1.9.1/bundler/gems/spree-afcc23e489eb/core/app/views/spree/admin/shared/_translations.html.erb (1.0ms)
  Rendered /home/vagrant/.gem/ruby/1.9.1/bundler/gems/spree-afcc23e489eb/core/app/views/spree/admin/shared/_routes.html.erb (0.7ms)
  Rendered /home/vagrant/.gem/ruby/1.9.1/bundler/gems/spree-afcc23e489eb/core/app/views/spree/admin/shared/_head.html.erb (3.2ms)
  Rendered /home/vagrant/.gem/ruby/1.9.1/bundler/gems/spree-afcc23e489eb/core/app/views/spree/admin/shared/_alert.html.erb (0.0ms)
  Rendered spree/admin/shared/_tabs.html.erb (17.4ms)
  Rendered spree/admin/shared/_trial_progress_bar.html.haml (0.1ms)
  Rendered shared/_analytics.html.haml (0.1ms)
Completed 200 OK in 240.5ms (Views: 197.4ms | ActiveRecord: 8.3ms)
Started POST "/admin/enterprises" for 127.0.0.1 at 2015-09-18 06:35:10 +0000
Processing by Admin::EnterprisesController#create as HTML
  Parameters: {"utf8"=>"✓", "enterprise"=>{"name"=>"", "owner_id"=>"", "is_primary_producer"=>"0", "sells"=>"none", "contact"=>"", "email"=>"mike@mzoo.org", "phone"=>"201-679-4168", "website"=>"", "address_attributes"=>{"address1"=>"123 S. Bloomfield Ave.", "address2"=>"", "city"=>"Montawk", "zipcode"=>"10009", "state_id"=>"39", "country_id"=>"49"}}, "button"=>""}
  Spree::User Load (0.4ms)  SELECT "spree_users".* FROM "spree_users" WHERE "spree_users"."id" = 1 LIMIT 1
   (0.4ms)  SELECT COUNT(*) FROM "spree_roles" INNER JOIN "spree_roles_users" ON "spree_roles"."id" = "spree_roles_users"."role_id" WHERE "spree_roles_users"."user_id" = 1 AND "spree_roles"."name" = 'admin'
  Enterprise Load (0.5ms)  SELECT "enterprises".* FROM "enterprises" INNER JOIN "enterprise_roles" ON "enterprises"."id" = "enterprise_roles"."enterprise_id" WHERE "enterprise_roles"."user_id" = 1
  EnterpriseGroup Load (0.4ms)  SELECT "enterprise_groups".* FROM "enterprise_groups" WHERE "enterprise_groups"."owner_id" = 1
  CACHE (0.0ms)  SELECT COUNT(*) FROM "spree_roles" INNER JOIN "spree_roles_users" ON "spree_roles"."id" = "spree_roles_users"."role_id" WHERE "spree_roles_users"."user_id" = 1 AND "spree_roles"."name" = 'admin'
   (0.2ms)  SELECT COUNT(*) FROM "order_cycles" 
  Spree::Country Load (0.3ms)  SELECT "spree_countries".* FROM "spree_countries" WHERE "spree_countries"."id" = 49 LIMIT 1
  CACHE (0.0ms)  SELECT COUNT(*) FROM "spree_roles" INNER JOIN "spree_roles_users" ON "spree_roles"."id" = "spree_roles_users"."role_id" WHERE "spree_roles_users"."user_id" = 1 AND "spree_roles"."name" = 'admin'
  OrderCycle Load (0.3ms)  SELECT "order_cycles".* FROM "order_cycles" WHERE (order_cycles.orders_open_at <= '2015-09-18 06:35:10.695636' AND order_cycles.orders_close_at >= '2015-09-18 06:35:10.695640')
   (1.0ms)  SELECT COUNT(*) FROM "enterprises" INNER JOIN "distributors_shipping_methods" ON "distributors_shipping_methods"."distributor_id" = "enterprises"."id" INNER JOIN "spree_shipping_methods" ON "spree_shipping_methods"."id" = "distributors_shipping_methods"."shipping_method_id" INNER JOIN "distributors_payment_methods" ON "distributors_payment_methods"."distributor_id" = "enterprises"."id" INNER JOIN "spree_payment_methods" ON "spree_payment_methods"."id" = "distributors_payment_methods"."payment_method_id" WHERE "spree_payment_methods"."deleted_at" IS NULL AND "spree_payment_methods"."active" = 't' AND (spree_payment_methods.display_on='both' OR spree_payment_methods.display_on='' OR spree_payment_methods.display_on IS NULL) AND (spree_payment_methods.environment='test' OR spree_payment_methods.environment='' OR spree_payment_methods.environment IS NULL)
  CACHE (0.0ms)  SELECT COUNT(*) FROM "enterprises" INNER JOIN "distributors_shipping_methods" ON "distributors_shipping_methods"."distributor_id" = "enterprises"."id" INNER JOIN "spree_shipping_methods" ON "spree_shipping_methods"."id" = "distributors_shipping_methods"."shipping_method_id" INNER JOIN "distributors_payment_methods" ON "distributors_payment_methods"."distributor_id" = "enterprises"."id" INNER JOIN "spree_payment_methods" ON "spree_payment_methods"."id" = "distributors_payment_methods"."payment_method_id" WHERE "spree_payment_methods"."deleted_at" IS NULL AND "spree_payment_methods"."active" = 't' AND (spree_payment_methods.display_on='both' OR spree_payment_methods.display_on='' OR spree_payment_methods.display_on IS NULL) AND (spree_payment_methods.environment='test' OR spree_payment_methods.environment='' OR spree_payment_methods.environment IS NULL)
   (0.3ms)  SELECT COUNT(*) FROM "enterprises" WHERE (id IN (NULL)) AND (id NOT IN (NULL) OR 0=0)
  CACHE (0.0ms)  SELECT COUNT(*) FROM "spree_roles" INNER JOIN "spree_roles_users" ON "spree_roles"."id" = "spree_roles_users"."role_id" WHERE "spree_roles_users"."user_id" = 1 AND "spree_roles"."name" = 'admin'
  Spree::PaymentMethod Load (0.2ms)  SELECT "spree_payment_methods".* FROM "spree_payment_methods" WHERE "spree_payment_methods"."deleted_at" IS NULL
  CACHE (0.0ms)  SELECT COUNT(*) FROM "spree_roles" INNER JOIN "spree_roles_users" ON "spree_roles"."id" = "spree_roles_users"."role_id" WHERE "spree_roles_users"."user_id" = 1 AND "spree_roles"."name" = 'admin'
  Spree::ShippingMethod Load (0.3ms)  SELECT "spree_shipping_methods".* FROM "spree_shipping_methods" WHERE "spree_shipping_methods"."deleted_at" IS NULL
  CACHE (0.0ms)  SELECT COUNT(*) FROM "spree_roles" INNER JOIN "spree_roles_users" ON "spree_roles"."id" = "spree_roles_users"."role_id" WHERE "spree_roles_users"."user_id" = 1 AND "spree_roles"."name" = 'admin'
  EnterpriseFee Load (0.4ms)  SELECT "enterprise_fees".* FROM "enterprise_fees" WHERE "enterprise_fees"."enterprise_id" IS NULL ORDER BY fee_type, name
  CACHE (0.0ms)  SELECT COUNT(*) FROM "spree_roles" INNER JOIN "spree_roles_users" ON "spree_roles"."id" = "spree_roles_users"."role_id" WHERE "spree_roles_users"."user_id" = 1 AND "spree_roles"."name" = 'admin'
  EnterpriseGroup Load (0.4ms)  SELECT "enterprise_groups".* FROM "enterprise_groups" 
  CACHE (0.0ms)  SELECT COUNT(*) FROM "spree_roles" INNER JOIN "spree_roles_users" ON "spree_roles"."id" = "spree_roles_users"."role_id" WHERE "spree_roles_users"."user_id" = 1 AND "spree_roles"."name" = 'admin'
  CACHE (0.0ms)  SELECT COUNT(*) FROM "spree_roles" INNER JOIN "spree_roles_users" ON "spree_roles"."id" = "spree_roles_users"."role_id" WHERE "spree_roles_users"."user_id" = 1 AND "spree_roles"."name" = 'admin'
  CACHE (0.0ms)  SELECT COUNT(*) FROM "spree_roles" INNER JOIN "spree_roles_users" ON "spree_roles"."id" = "spree_roles_users"."role_id" WHERE "spree_roles_users"."user_id" = 1 AND "spree_roles"."name" = 'admin'
   (0.1ms)  BEGIN
  Enterprise Load (0.4ms)  SELECT permalink FROM "enterprises" WHERE (permalink LIKE 'my-enterprise%') ORDER BY permalink
  CACHE (0.0ms)  SELECT "spree_countries".* FROM "spree_countries" WHERE "spree_countries"."id" = 49 LIMIT 1
  Spree::State Load (0.3ms)  SELECT "spree_states".* FROM "spree_states" WHERE "spree_states"."id" = 39 LIMIT 1
  CACHE (0.0ms)  SELECT "spree_countries".* FROM "spree_countries" WHERE "spree_countries"."id" = 49 LIMIT 1
  Spree::State Load (0.4ms)  SELECT "spree_states".* FROM "spree_states" WHERE "spree_states"."country_id" = 49 ORDER BY name ASC
   (0.4ms)  SELECT COUNT(*) FROM "spree_states" WHERE "spree_states"."country_id" = 49 AND (name = 'Alabama' OR abbr = 'Alabama')
  Spree::State Load (0.3ms)  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.3ms)  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.3ms)  SELECT 1 AS one FROM "enterprises" WHERE "enterprises"."permalink" = 'my-enterprise' LIMIT 1
   (0.1ms)  ROLLBACK
Completed 500 Internal Server Error in 69.5ms
** [Bugsnag] No API key configured, couldn't notify

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 ?

1 Like

Good thinking!

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

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.

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;


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=#