Need help to fix ERR 500

Hi,
I try to to install and deploy the OFN from ofn_deployment in France. (I’m working on this with Myriam @myriam )
Then I follow the informations on the github page.
The installation process looks ok. I can log in the OFN website on my new server. But when I try to create a new company, I get an HTTP ERR 500.
I jus get this log on log/test.log :

(0.2ms) BEGIN
Enterprise Load (0.4ms) SELECT permalink FROM “enterprises” WHERE (permalink LIKE ‘nollet%’) ORDER BY permalink
CACHE (0.0ms) SELECT “spree_users”.* FROM “spree_users” WHERE “spree_users”.“id” = 1 LIMIT 1
Spree::User Exists (0.5ms) SELECT 1 AS one FROM “spree_users” INNER JOIN “enterprise_roles” ON “spree_users”.“id” = “enterprise_roles”.“user_id” WHERE “enterprise_roles”.“enterprise_id” IS NULL AND “spree_users”.“id” = 1 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’
CACHE (0.0ms) SELECT “spree_countries”.
FROM “spree_countries” WHERE “spree_countries”.“id” = 13 LIMIT 1
Spree::State Load (0.4ms) SELECT “spree_states”.* FROM “spree_states” WHERE “spree_states”.“id” = 150 LIMIT 1
CACHE (0.0ms) SELECT “spree_countries”.* FROM “spree_countries” WHERE “spree_countries”.“id” = 13 LIMIT 1
Spree::State Load (1.0ms) SELECT “spree_states”.* FROM “spree_states” WHERE “spree_states”.“country_id” = 13 ORDER BY name ASC
(0.4ms) SELECT COUNT() FROM “spree_states” WHERE “spree_states”.“country_id” = 13 AND (name = ‘VAL D OISE’ OR abbr = ‘VAL D OISE’)
Spree::State Load (0.4ms) SELECT “spree_states”.
FROM “spree_states” WHERE “spree_states”.“country_id” = 13 AND (name = ‘VAL D OISE’ OR abbr = ‘VAL D OISE’) ORDER BY name ASC LIMIT 1
(0.4ms) SELECT COUNT() FROM “enterprises” WHERE “enterprises”.“name” = 'NOLLET’
CACHE (0.0ms) SELECT “spree_countries”.
FROM “spree_countries” WHERE “spree_countries”.“id” = 13 LIMIT 1
CACHE (0.0ms) SELECT COUNT() FROM “spree_states” WHERE “spree_states”.“country_id” = 13 AND (name = ‘VAL D OISE’ OR abbr = ‘VAL D OISE’)
CACHE (0.0ms) SELECT “spree_states”.
FROM “spree_states” WHERE “spree_states”.“country_id” = 13 AND (name = ‘VAL D OISE’ OR abbr = ‘VAL D OISE’) ORDER BY name ASC LIMIT 1
Enterprise Exists (0.4ms) SELECT 1 AS one FROM “enterprises” WHERE “enterprises”.“permalink” = ‘nollet’ LIMIT 1
Enterprise Load (0.5ms) SELECT “enterprises”.* FROM “enterprises” WHERE “enterprises”.“owner_id” = 1
(0.2ms) ROLLBACK
Completed 500 Internal Server Error in 75.4ms
** [Bugsnag] No API key configured, couldn’t notify

Then, I don’t know where to search to identify the error.

If anyone can help us, that would be great.

Thanks a lot
Gilles

Do you know who could have an idea on that, apart from Rohan who is in holidays @Kirsten ?
@gnollet you used Ansible? Did you manage to deploy without the i10n_fr repository?
You also said you had a problem with the mail server, no?

Yes, I used Ansible. I run the playbook as explained.

On the playbook, I replace the part of the seeds file by the French seeds files.

On the mail config, I tried different config :

  • use the local mail server (postfix)
  • use AWS SES
  • try to use sendgrid
    When I try to generate a test email from admin backend, I can see the mail generated on the log file but I don’t receive any email.
    Even if I test with postfix config which is local, I didn’t see any mail coming from website.

Then I don’t know how to fix this.

could this email problem be anything to do with delayed job? @pmackay?

I’m having a similar error, also on Vagrant box set up with ofn_deployment repo via Ansible.

May be a Spree issue and am filing there as well.

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