My app can't send order invoices and gives this error in the production.log:
I, [2017-05-21T17:17:19.539388 #9385] INFO -- : Completed 500 Internal Server Error in 26ms (ActiveRecord: 3.1ms)
F, [2017-05-21T17:17:19.540462 #9385] FATAL -- :
Errno::ECONNREFUSED (Connection refused - connect(2) for nil port 587):
app/admin/order.rb:6:in `block (2 levels) in <top (required)>'
My cloud services support sent me this answer : I ran an NMAP on your IP address and port 587 appears to be blocked locally on your Droplet. Usually this is caused by IPtables or UFW trying to be helpful, but actually blocking a needed port.
So I did sudo iptables -A OUTPUT -p tcp --dport 587 -j ACCEPT and sudo ufw allow out 587
That didn't do the trick and I'm still getting this error. Can someone please advise me?
here is the action mailersettings in the production.rb
config.action_mailer.default_url_options = { host: 'mypage.com'}
config.action_mailer.perform_deliveries = true
config.action_mailer.raise_delivery_errors = true
config.action_mailer.delivery_method = :smtp
config.action_mailer.smtp_settings = {
address: ENV["SMTP_ADDRESS"],
user_name: ENV["SMTP_USER"],
password: ENV["SMTP_PASSWORD"],
domain: "mypage.com",
port: 587,
authentication: :login,
enable_starttls_auto: true
}
In the deploy.rb I have this line to to trigger a copy of figaros application.yml to the server.
set :linked_files, %w{config/database.yml config/secrets.yml config/application.yml}
I'm using figaro gem
in the application.yml there is this lines:
SMTP_ADDRESS: "smtp.gmail.com"
SMTP_USER: "[email protected]"
SMTP_PASSWORD: "xxxxxx"
** UPdate-3**
I, [2017-05-23T11:01:33.056948 #1060] INFO -- : Started GET "/admin/orders/10/edit" for 89.160.235.185 at 2017-05-23 11:01:33 +0000
I, [2017-05-23T11:01:33.063914 #1060] INFO -- : Processing by Admin::OrdersController#edit as HTML
I, [2017-05-23T11:01:33.064026 #1060] INFO -- : Parameters: {"id"=>"10"}
D, [2017-05-23T11:01:33.067956 #1060] DEBUG -- : ^[[1m^[[36mCart Load (0.5ms)^[[0m ^[[1mSELECT "carts".* FROM "carts" WHERE "carts"."id" = $1 LIMIT 1^[[0m [["$
D, [2017-05-23T11:01:33.072547 #1060] DEBUG -- : ^[[1m^[[35mAdminUser Load (0.4ms)^[[0m SELECT "admin_users".* FROM "admin_users" WHERE "admin_users"."id" = $1$
D, [2017-05-23T11:01:33.075089 #1060] DEBUG -- : ^[[1m^[[36mOrder Load (0.3ms)^[[0m ^[[1mSELECT "orders".* FROM "orders" WHERE "orders"."id" = $1 LIMIT 1^[[0m $
D, [2017-05-23T11:01:33.119522 #1060] DEBUG -- : ^[[1m^[[35mCACHE (0.0ms)^[[0m SELECT "orders".* FROM "orders" WHERE "orders"."id" = $1 LIMIT 1 [["id", "10"]]
I, [2017-05-23T11:01:33.235247 #1060] INFO -- : Rendered /home/deploy/hlinreykdal/shared/bundle/ruby/2.3.0/bundler/gems/activeadmin-0a5a15b88bff/app/views/activ$
I, [2017-05-23T11:01:33.235589 #1060] INFO -- : Completed 200 OK in 171ms (Views: 157.9ms | ActiveRecord: 1.2ms)
I, [2017-05-23T11:01:36.922087 #1060] INFO -- : Started PATCH "/admin/orders/10" for 89.160.235.185 at 2017-05-23 11:01:36 +0000
I, [2017-05-23T11:01:36.924303 #1060] INFO -- : Processing by Admin::OrdersController#update as HTML
I, [2017-05-23T11:01:36.924405 #1060] INFO -- : Parameters: {"utf8"=>" ^ ^ ", "authenticity_token"=>"f8ApZNwgnz1TpSUFfXOkVb2/QnTZaz2p0j3cWIcmdBxRzZpmmWJLQmuDx+n$
D, [2017-05-23T11:01:36.925594 #1060] DEBUG -- : ^[[1m^[[36mCart Load (0.2ms)^[[0m ^[[1mSELECT "carts".* FROM "carts" WHERE "carts"."id" = $1 LIMIT 1^[[0m [["$
D, [2017-05-23T11:01:36.926750 #1060] DEBUG -- : ^[[1m^[[35mAdminUser Load (0.2ms)^[[0m SELECT "admin_users".* FROM "admin_users" WHERE "admin_users"."id" = $1$
D, [2017-05-23T11:01:36.957134 #1060] DEBUG -- : ^[[1m^[[36mOrder Load (0.3ms)^[[0m ^[[1mSELECT "orders".* FROM "orders" WHERE "orders"."id" = $1 LIMIT 1^[[0m $
D, [2017-05-23T11:01:36.958757 #1060] DEBUG -- : ^[[1m^[[35m (0.1ms)^[[0m BEGIN
D, [2017-05-23T11:01:36.961249 #1060] DEBUG -- : ^[[1m^[[36mSQL (0.6ms)^[[0m ^[[1mUPDATE "orders" SET "shipped" = $1, "updated_at" = $2 WHERE "orders"."id" = $3$
D, [2017-05-23T11:01:36.962569 #1060] DEBUG -- : ^[[1m^[[35m (0.8ms)^[[0m COMMIT
I, [2017-05-23T11:01:36.965057 #1060] INFO -- : Redirected to http://hlinreykdal.com/admin/orders/10
I, [2017-05-23T11:01:36.965267 #1060] INFO -- : Completed 302 Found in 41ms (ActiveRecord: 2.3ms)
I, [2017-05-23T11:01:37.013697 #1060] INFO -- : Started GET "/admin/orders/10" for 89.160.235.185 at 2017-05-23 11:01:37 +0000
I, [2017-05-23T11:01:37.014844 #1060] INFO -- : Processing by Admin::OrdersController#show as HTML
I, [2017-05-23T11:01:37.014925 #1060] INFO -- : Parameters: {"id"=>"10"}
D, [2017-05-23T11:01:37.015893 #1060] DEBUG -- : ^[[1m^[[36mCart Load (0.2ms)^[[0m ^[[1mSELECT "carts".* FROM "carts" WHERE "carts"."id" = $1 LIMIT 1^[[0m [["$
D, [2017-05-23T11:01:37.017087 #1060] DEBUG -- : ^[[1m^[[35mAdminUser Load (0.2ms)^[[0m SELECT "admin_users".* FROM "admin_users" WHERE "admin_users"."id" = $1$
D, [2017-05-23T11:01:37.017985 #1060] DEBUG -- : ^[[1m^[[36mOrder Load (0.2ms)^[[0m ^[[1mSELECT "orders".* FROM "orders" WHERE "orders"."id" = $1 LIMIT 1^[[0m $
D, [2017-05-23T11:01:37.046277 #1060] DEBUG -- : ^[[1m^[[35mProductItem Load (0.9ms)^[[0m SELECT "product_items".* FROM "product_items" WHERE "product_items"."o$
D, [2017-05-23T11:01:37.048060 #1060] DEBUG -- : ^[[1m^[[36mProduct Load (0.3ms)^[[0m ^[[1mSELECT "products".* FROM "products" WHERE "products"."id" = $1 LIMIT$
I, [2017-05-23T11:01:37.055910 #1060] INFO -- : Rendered /home/deploy/hlinreykdal/shared/bundle/ruby/2.3.0/bundler/gems/activeadmin-0a5a15b88bff/app/views/activ$
I, [2017-05-23T11:01:37.056193 #1060] INFO -- : Completed 200 OK in 41ms (Views: 36.4ms | ActiveRecord: 1.7ms)
I, [2017-05-23T11:01:39.569747 #1060] INFO -- : Started GET "/admin/orders" for 89.160.235.185 at 2017-05-23 11:01:39 +0000
I, [2017-05-23T11:01:39.571136 #1060] INFO -- : Processing by Admin::OrdersController#index as HTML
D, [2017-05-23T11:01:39.572365 #1060] DEBUG -- : ^[[1m^[[35mCart Load (0.2ms)^[[0m SELECT "carts".* FROM "carts" WHERE "carts"."id" = $1 LIMIT 1 [["id", 45856$
D, [2017-05-23T11:01:39.573735 #1060] DEBUG -- : ^[[1m^[[36mAdminUser Load (0.2ms)^[[0m ^[[1mSELECT "admin_users".* FROM "admin_users" WHERE "admin_users"."id"$
D, [2017-05-23T11:01:39.601594 #1060] DEBUG -- : ^[[1m^[[35m (0.6ms)^[[0m SELECT COUNT(count_column) FROM (SELECT 1 AS count_column FROM "orders" LIMIT 30 OFFS$
D, [2017-05-23T11:01:39.602587 #1060] DEBUG -- : ^[[1m^[[36mCACHE (0.0ms)^[[0m ^[[1mSELECT COUNT(count_column) FROM (SELECT 1 AS count_column FROM "orders" LIM$
D, [2017-05-23T11:01:39.603970 #1060] DEBUG -- : ^[[1m^[[35m (0.3ms)^[[0m SELECT COUNT(*) FROM "orders"
D, [2017-05-23T11:01:39.605077 #1060] DEBUG -- : ^[[1m^[[36mCACHE (0.0ms)^[[0m ^[[1mSELECT COUNT(count_column) FROM (SELECT 1 AS count_column FROM "orders" LIM$
D, [2017-05-23T11:01:39.607023 #1060] DEBUG -- : ^[[1m^[[35mOrder Load (0.4ms)^[[0m SELECT "orders".* FROM "orders" ORDER BY "orders"."id" desc LIMIT 30 OFFSE$
D, [2017-05-23T11:01:39.630054 #1060] DEBUG -- : ^[[1m^[[36mProductItem Load (0.4ms)^[[0m ^[[1mSELECT "product_items".* FROM "product_items"^[[0m
I, [2017-05-23T11:01:39.675343 #1060] INFO -- : Rendered /home/deploy/hlinreykdal/shared/bundle/ruby/2.3.0/bundler/gems/activeadmin-0a5a15b88bff/app/views/activ$
I, [2017-05-23T11:01:39.675662 #1060] INFO -- : Completed 200 OK in 104ms (Views: 98.1ms | ActiveRecord: 2.2ms)
I, [2017-05-23T11:01:42.003418 #1060] INFO -- : Started GET "/admin/orders/10/edit" for 89.160.235.185 at 2017-05-23 11:01:42 +0000
I, [2017-05-23T11:01:42.005829 #1060] INFO -- : Processing by Admin::OrdersController#edit as HTML
I, [2017-05-23T11:01:42.005923 #1060] INFO -- : Parameters: {"id"=>"10"}
D, [2017-05-23T11:01:42.007115 #1060] DEBUG -- : ^[[1m^[[35mCart Load (0.2ms)^[[0m SELECT "carts".* FROM "carts" WHERE "carts"."id" = $1 LIMIT 1 [["id", 45856$
D, [2017-05-23T11:01:42.008543 #1060] DEBUG -- : ^[[1m^[[36mAdminUser Load (0.2ms)^[[0m ^[[1mSELECT "admin_users".* FROM "admin_users" WHERE "admin_users"."id"$
D, [2017-05-23T11:01:42.009473 #1060] DEBUG -- : ^[[1m^[[35mOrder Load (0.2ms)^[[0m SELECT "orders".* FROM "orders" WHERE "orders"."id" = $1 LIMIT 1 [["id", 1$
D, [2017-05-23T11:01:42.030642 #1060] DEBUG -- : ^[[1m^[[36mCACHE (0.0ms)^[[0m ^[[1mSELECT "orders".* FROM "orders" WHERE "orders"."id" = $1 LIMIT 1^[[0m [["i$
I, [2017-05-23T11:01:42.096028 #1060] INFO -- : Rendered /home/deploy/hlinreykdal/shared/bundle/ruby/2.3.0/bundler/gems/activeadmin-0a5a15b88bff/app/views/activ$
I, [2017-05-23T11:01:42.096369 #1060] INFO -- : Completed 200 OK in 90ms (Views: 86.2ms | ActiveRecord: 0.6ms)
I, [2017-05-23T11:01:44.668194 #1060] INFO -- : Started PATCH "/admin/orders/10" for 89.160.235.185 at 2017-05-23 11:01:44 +0000
I, [2017-05-23T11:01:44.674148 #1060] INFO -- : Processing by Admin::OrdersController#update as HTML
I, [2017-05-23T11:01:44.674417 #1060] INFO -- : Parameters: {"utf8"=>" ^ ^ ", "authenticity_token"=>"NcVZXJWZ1pcKMTEmFFZmtY3HvY7oJH2G+WOxTpVXu6UbyOpe0NsC6DIX08q$
D, [2017-05-23T11:01:44.681838 #1060] DEBUG -- : ^[[1m^[[35mCart Load (1.6ms)^[[0m SELECT "carts".* FROM "carts" WHERE "carts"."id" = $1 LIMIT 1 [["id", 45856$
D, [2017-05-23T11:01:44.687054 #1060] DEBUG -- : ^[[1m^[[36mAdminUser Load (0.4ms)^[[0m ^[[1mSELECT "admin_users".* FROM "admin_users" WHERE "admin_users"."id"$
D, [2017-05-23T11:01:44.690370 #1060] DEBUG -- : ^[[1m^[[35mOrder Load (0.4ms)^[[0m SELECT "orders".* FROM "orders" WHERE "orders"."id" = $1 LIMIT 1 [["id", 1$
D, [2017-05-23T11:01:44.694556 #1060] DEBUG -- : ^[[1m^[[36m (0.1ms)^[[0m ^[[1mBEGIN^[[0m
D, [2017-05-23T11:01:44.699039 #1060] DEBUG -- : ^[[1m^[[35mSQL (0.4ms)^[[0m UPDATE "orders" SET "shipped" = $1, "updated_at" = $2 WHERE "orders"."id" = $3 [["$
D, [2017-05-23T11:01:44.700660 #1060] DEBUG -- : ^[[1m^[[36m (0.7ms)^[[0m ^[[1mCOMMIT^[[0m
I, [2017-05-23T11:01:44.703571 #1060] INFO -- : SMTP_ADDR: "smtp.gmail.com"
D, [2017-05-23T11:01:44.707271 #1060] DEBUG -- : ^[[1m^[[35mProductItem Load (0.3ms)^[[0m SELECT "product_items".* FROM "product_items" WHERE "product_items"."o$
D, [2017-05-23T11:01:44.708898 #1060] DEBUG -- : ^[[1m^[[36mProduct Load (0.3ms)^[[0m ^[[1mSELECT "products".* FROM "products" WHERE "products"."id" = $1 LIMIT$
I, [2017-05-23T11:01:44.709746 #1060] INFO -- : Rendered order_notifier/shipped.html.erb within layouts/mailer (4.5ms)
D, [2017-05-23T11:01:44.711077 #1060] DEBUG -- :
OrderNotifier#shipped: processed outbound mail in 8.1ms
I, [2017-05-23T11:01:44.739622 #1060] INFO -- :
Sent mail to [email protected] (28.3ms)
D, [2017-05-23T11:01:44.739727 #1060] DEBUG -- : Date: Tue, 23 May 2017 11:01:44 +0000
From: =?UTF-8?B?SGzDrW4=?= Reykdal Concept Store <[email protected]>
To: [email protected]
Message-ID: <[email protected]>
Subject: Order Shipped
Mime-Version: 1.0
Content-Type: text/html;
charset=UTF-8
Content-Transfer-Encoding: 7bit
<html>
<body>
<h1>Your Order has been shipped</h1>
<h3>Dear dadi </h3>
<p>
Your order has been shipped to your address, please contact [email protected] for further information.
</p>
<p> Thank You </p>
<ul>
<li>
FOLLY MATCHBOOK NAIL FILES×1
</li>
</ul>
<p> Thank You </p>
</body>
</html>
I, [2017-05-23T11:01:44.741054 #1060] INFO -- : Completed 500 Internal Server Error in 66ms (ActiveRecord: 4.2ms)
F, [2017-05-23T11:01:44.743481 #1060] FATAL -- :
SocketError (getaddrinfo: Name or service not known):
app/admin/order.rb:6:in `block (2 levels) in <top (required)>'
I, [2017-05-23T11:10:08.863192 #1060] INFO -- : Started GET "/products/41" for 164.132.161.46 at 2017-05-23 11:10:08 +0000
I, [2017-05-23T11:10:08.876373 #1060] INFO -- : Processing by ProductsController#show as */*
I, [2017-05-23T11:10:08.876536 #1060] INFO -- : Parameters: {"id"=>"41"}
D, [2017-05-23T11:10:08.881123 #1060] DEBUG -- : ^[[1m^[[35mCart Load (0.7ms)^[[0m SELECT "carts".* FROM "carts" WHERE "carts"."id" = $1 LIMIT 1 [["id", nil]]
D, [2017-05-23T11:10:08.882685 #1060] DEBUG -- : ^[[1m^[[36m (0.2ms)^[[0m ^[[1mBEGIN^[[0m
D, [2017-05-23T11:10:08.887770 #1060] DEBUG -- : ^[[1m^[[35mSQL (1.3ms)^[[0m INSERT INTO "carts" ("created_at", "updated_at") VALUES ($1, $2) RETURNING "id" [[$
D, [2017-05-23T11:10:08.890018 #1060] DEBUG -- : ^[[1m^[[36m (0.7ms)^[[0m ^[[1mCOMMIT^[[0m
D, [2017-05-23T11:10:08.893274 #1060] DEBUG -- : ^[[1m^[[35mProduct Load (1.2ms)^[[0m SELECT "products".* FROM "products" WHERE "products"."slug" = $1 ORDER B$
D, [2017-05-23T11:10:08.894865 #1060] DEBUG -- : ^[[1m^[[36mProduct Load (0.4ms)^[[0m ^[[1mSELECT "products".* FROM "products" WHERE "products"."id" = $1 LIMIT$
D, [2017-05-23T11:10:08.900733 #1060] DEBUG -- : ^[[1m^[[35mLabel Load (1.2ms)^[[0m SELECT "labels".* FROM "labels" WHERE "labels"."id" = $1 LIMIT 1 [["id", 8$
D, [2017-05-23T11:10:08.907954 #1060] DEBUG -- : ^[[1m^[[36mProduct Load (0.6ms)^[[0m ^[[1mSELECT "products".* FROM "products" WHERE "products"."category_id" =$
I, [2017-05-23T11:10:08.916955 #1060] INFO -- : Rendered products/show.html.erb within layouts/application (18.7ms)
D, [2017-05-23T11:10:08.920965 #1060] DEBUG -- : ^[[1m^[[35mCategory Load (0.8ms)^[[0m SELECT "categories".* FROM "categories"
D, [2017-05-23T11:10:08.924524 #1060] DEBUG -- : ^[[1m^[[36mLabel Load (0.3ms)^[[0m ^[[1mSELECT "labels".* FROM "labels"^[[0m
D, [2017-05-23T11:10:08.929926 #1060] DEBUG -- : ^[[1m^[[35m (0.3ms)^[[0m SELECT COUNT(*) FROM "product_items" WHERE "product_items"."cart_id" = $1 [["cart_id"$
I, [2017-05-23T11:10:08.930159 #1060] INFO -- : Rendered application/_navbar.html.erb (10.7ms)
I, [2017-05-23T11:10:08.931046 #1060] INFO -- : Rendered application/_message.html.erb (0.2ms)
I, [2017-05-23T11:10:08.932261 #1060] INFO -- : Rendered emaillist/_email.html.erb (0.6ms)
I, [2017-05-23T11:10:08.932381 #1060] INFO -- : Rendered application/_notifications.html.erb (0.9ms)
I, [2017-05-23T11:10:08.936424 #1060] INFO -- : Rendered application/_footer.html.erb (3.5ms)
I, [2017-05-23T11:10:08.936826 #1060] INFO -- : Completed 200 OK in 60ms (Views: 36.7ms | ActiveRecord: 7.6ms)
I, [2017-05-23T11:12:35.005157 #1060] INFO -- : Started GET "/labels/10" for 66.249.65.74 at 2017-05-23 11:12:35 +0000
I, [2017-05-23T11:12:35.040137 #1060] INFO -- : Processing by LabelsController#show as HTML
I, [2017-05-23T11:12:35.040544 #1060] INFO -- : Parameters: {"id"=>"10"}
D, [2017-05-23T11:12:35.049755 #1060] DEBUG -- : ^[[1m^[[36mCart Load (0.8ms)^[[0m ^[[1mSELECT "carts".* FROM "carts" WHERE "carts"."id" = $1 LIMIT 1^[[0m [["$
D, [2017-05-23T11:12:35.052776 #1060] DEBUG -- : ^[[1m^[[35m (0.2ms)^[[0m BEGIN
D, [2017-05-23T11:12:35.060048 #1060] DEBUG -- : ^[[1m^[[36mSQL (0.9ms)^[[0m ^[[1mINSERT INTO "carts" ("created_at", "updated_at") VALUES ($1, $2) RETURNING "id$
D, [2017-05-23T11:12:35.061486 #1060] DEBUG -- : ^[[1m^[[35m (0.6ms)^[[0m COMMIT
D, [2017-05-23T11:12:35.065373 #1060] DEBUG -- : ^[[1m^[[36mLabel Load (0.4ms)^[[0m ^[[1mSELECT "labels".* FROM "labels" WHERE "labels"."id" = $1 LIMIT 1^[[0m $
I, [2017-05-23T11:12:35.067624 #1060] INFO -- : Completed 404 Not Found in 27ms (ActiveRecord: 3.0ms)
F, [2017-05-23T11:12:35.069957 #1060] FATAL -- :
ActiveRecord::RecordNotFound (Couldn't find Label with 'id'=10):
app/controllers/labels_controller.rb:21:in `set_label'