bvpb/log file for spree gateway issue

## log file for spree gateway issue
Started GET "/assets/responsive-tables.css?body=1" for 127.0.0.1 at 2013-10-06 16:27:01 +1100


Started GET "/assets/jquery.alerts/jquery.alerts.spree.css?body=1" for 127.0.0.1 at 2013-10-06 16:27:01 +1100


Started GET "/assets/jquery.alerts/jquery.alerts.css?body=1" for 127.0.0.1 at 2013-10-06 16:27:01 +1100


Started GET "/assets/jquery.ui.core.css?body=1" for 127.0.0.1 at 2013-10-06 16:27:01 +1100


Started GET "/assets/skeleton.css?body=1" for 127.0.0.1 at 2013-10-06 16:27:01 +1100


Started GET "/assets/normalize.css?body=1" for 127.0.0.1 at 2013-10-06 16:27:01 +1100


Started GET "/assets/jquery.ui.theme.css?body=1" for 127.0.0.1 at 2013-10-06 16:27:01 +1100


Started GET "/assets/jquery.ui.datepicker.css?body=1" for 127.0.0.1 at 2013-10-06 16:27:01 +1100


Started GET "/assets/jquery.ui.menu.css?body=1" for 127.0.0.1 at 2013-10-06 16:27:01 +1100


Started GET "/assets/jquery.ui.autocomplete.css?body=1" for 127.0.0.1 at 2013-10-06 16:27:01 +1100


Started GET "/assets/jquery.powertip.css?body=1" for 127.0.0.1 at 2013-10-06 16:27:01 +1100


Started GET "/assets/select2.css?body=1" for 127.0.0.1 at 2013-10-06 16:27:01 +1100


Started GET "/assets/admin/spree_admin.css?body=1" for 127.0.0.1 at 2013-10-06 16:27:01 +1100


Started GET "/assets/admin/spree_backend.css?body=1" for 127.0.0.1 at 2013-10-06 16:27:01 +1100


Started GET "/assets/admin/all.css?body=1" for 127.0.0.1 at 2013-10-06 16:27:01 +1100


Started GET "/assets/jquery.js?body=1" for 127.0.0.1 at 2013-10-06 16:27:01 +1100


Started GET "/assets/jquery_ujs.js?body=1" for 127.0.0.1 at 2013-10-06 16:27:01 +1100


Started GET "/assets/jquery-migrate-1.0.0.js?body=1" for 127.0.0.1 at 2013-10-06 16:27:01 +1100


Started GET "/assets/jquery.ui.core.js?body=1" for 127.0.0.1 at 2013-10-06 16:27:02 +1100


Started GET "/assets/jquery.ui.datepicker.js?body=1" for 127.0.0.1 at 2013-10-06 16:27:02 +1100


Started GET "/assets/jquery.ui.widget.js?body=1" for 127.0.0.1 at 2013-10-06 16:27:02 +1100


Started GET "/assets/jquery.ui.mouse.js?body=1" for 127.0.0.1 at 2013-10-06 16:27:02 +1100


Started GET "/assets/jquery.ui.sortable.js?body=1" for 127.0.0.1 at 2013-10-06 16:27:02 +1100


Started GET "/assets/jquery.ui.position.js?body=1" for 127.0.0.1 at 2013-10-06 16:27:02 +1100


Started GET "/assets/jquery.ui.menu.js?body=1" for 127.0.0.1 at 2013-10-06 16:27:02 +1100


Started GET "/assets/jquery.ui.autocomplete.js?body=1" for 127.0.0.1 at 2013-10-06 16:27:02 +1100


Started GET "/assets/modernizr.js?body=1" for 127.0.0.1 at 2013-10-06 16:27:02 +1100


Started GET "/assets/jquery.cookie.js?body=1" for 127.0.0.1 at 2013-10-06 16:27:02 +1100


Started GET "/assets/jquery.delayedobserver.js?body=1" for 127.0.0.1 at 2013-10-06 16:27:02 +1100


Started GET "/assets/jquery.jstree/jquery.jstree.js?body=1" for 127.0.0.1 at 2013-10-06 16:27:02 +1100


Started GET "/assets/jquery.alerts/jquery.alerts.js?body=1" for 127.0.0.1 at 2013-10-06 16:27:02 +1100


Started GET "/assets/jquery.powertip.js?body=1" for 127.0.0.1 at 2013-10-06 16:27:02 +1100


Started GET "/assets/jquery.vAlign.js?body=1" for 127.0.0.1 at 2013-10-06 16:27:02 +1100


Started GET "/assets/spin.js?body=1" for 127.0.0.1 at 2013-10-06 16:27:02 +1100


Started GET "/assets/css_browser_selector_dev.js?body=1" for 127.0.0.1 at 2013-10-06 16:27:02 +1100


Started GET "/assets/trunk8.js?body=1" for 127.0.0.1 at 2013-10-06 16:27:02 +1100


Started GET "/assets/jquery.adaptivemenu.js?body=1" for 127.0.0.1 at 2013-10-06 16:27:02 +1100


Started GET "/assets/equalize.js?body=1" for 127.0.0.1 at 2013-10-06 16:27:02 +1100


Started GET "/assets/responsive-tables.js?body=1" for 127.0.0.1 at 2013-10-06 16:27:02 +1100


Started GET "/assets/jsuri.js?body=1" for 127.0.0.1 at 2013-10-06 16:27:02 +1100


Started GET "/assets/spree.js?body=1" for 127.0.0.1 at 2013-10-06 16:27:02 +1100


Started GET "/assets/select2.js?body=1" for 127.0.0.1 at 2013-10-06 16:27:02 +1100


Started GET "/assets/admin/address_states.js?body=1" for 127.0.0.1 at 2013-10-06 16:27:02 +1100


Started GET "/assets/admin/spree-select2.js?body=1" for 127.0.0.1 at 2013-10-06 16:27:02 +1100


Started GET "/assets/admin/admin.js?body=1" for 127.0.0.1 at 2013-10-06 16:27:02 +1100


Started GET "/assets/admin/variant_autocomplete.js?body=1" for 127.0.0.1 at 2013-10-06 16:27:02 +1100


Started GET "/assets/handlebars.js?body=1" for 127.0.0.1 at 2013-10-06 16:27:02 +1100


Started GET "/assets/admin/handlebar_extensions.js?body=1" for 127.0.0.1 at 2013-10-06 16:27:02 +1100


Started GET "/assets/admin/taxon_autocomplete.js?body=1" for 127.0.0.1 at 2013-10-06 16:27:02 +1100


Started GET "/assets/admin/option_type_autocomplete.js?body=1" for 127.0.0.1 at 2013-10-06 16:27:02 +1100


Started GET "/assets/admin/user_picker.js?body=1" for 127.0.0.1 at 2013-10-06 16:27:02 +1100


Started GET "/assets/admin/product_picker.js?body=1" for 127.0.0.1 at 2013-10-06 16:27:02 +1100


Started GET "/assets/admin/calculator.js?body=1" for 127.0.0.1 at 2013-10-06 16:27:02 +1100


Started GET "/assets/admin/checkouts/edit.js?body=1" for 127.0.0.1 at 2013-10-06 16:27:03 +1100


Started GET "/assets/jquery.payment.js?body=1" for 127.0.0.1 at 2013-10-06 16:27:03 +1100


Started GET "/assets/admin/gateway.js?body=1" for 127.0.0.1 at 2013-10-06 16:27:03 +1100


Started GET "/assets/admin/image_settings.js?body=1" for 127.0.0.1 at 2013-10-06 16:27:03 +1100


Started GET "/assets/admin/images/index.js?body=1" for 127.0.0.1 at 2013-10-06 16:27:03 +1100


Started GET "/assets/admin/images/new.js?body=1" for 127.0.0.1 at 2013-10-06 16:27:03 +1100


Started GET "/assets/admin/nested-attribute.js?body=1" for 127.0.0.1 at 2013-10-06 16:27:03 +1100


Started GET "/assets/admin/orders/edit.js?body=1" for 127.0.0.1 at 2013-10-06 16:27:03 +1100


Started GET "/assets/admin/orders/edit_form.js?body=1" for 127.0.0.1 at 2013-10-06 16:27:03 +1100


Started GET "/assets/admin/payments/new.js?body=1" for 127.0.0.1 at 2013-10-06 16:27:03 +1100


Started GET "/assets/admin/progress.js?body=1" for 127.0.0.1 at 2013-10-06 16:27:03 +1100


Started GET "/assets/admin/shipments.js?body=1" for 127.0.0.1 at 2013-10-06 16:27:03 +1100


Started GET "/assets/admin/promotions.js?body=1" for 127.0.0.1 at 2013-10-06 16:27:03 +1100


Started GET "/assets/admin/states.js?body=1" for 127.0.0.1 at 2013-10-06 16:27:03 +1100


Started GET "/assets/admin/stock_management.js?body=1" for 127.0.0.1 at 2013-10-06 16:27:03 +1100


Started GET "/assets/admin/stock_transfer.js?body=1" for 127.0.0.1 at 2013-10-06 16:27:03 +1100


Started GET "/assets/admin/taxon_tree_menu.js?body=1" for 127.0.0.1 at 2013-10-06 16:27:03 +1100


Started GET "/assets/admin/taxonomy.js?body=1" for 127.0.0.1 at 2013-10-06 16:27:03 +1100


Started GET "/assets/admin/underscore-min.js?body=1" for 127.0.0.1 at 2013-10-06 16:27:03 +1100


Started GET "/assets/admin/zone.js?body=1" for 127.0.0.1 at 2013-10-06 16:27:03 +1100


Started GET "/assets/admin/spree_backend.js?body=1" for 127.0.0.1 at 2013-10-06 16:27:03 +1100


Started GET "/assets/admin/all.js?body=1" for 127.0.0.1 at 2013-10-06 16:27:03 +1100


Started GET "/assets/logo/spree_50.png" for 127.0.0.1 at 2013-10-06 16:27:03 +1100


Started PATCH "/admin/payment_methods/6" for 127.0.0.1 at 2013-10-06 16:27:09 +1100
Processing by Spree::Admin::PaymentMethodsController#update as HTML
  Parameters: {"utf8"=>"✓", "authenticity_token"=>"ULTMChoByuqOylMyc2kVfmDUPIWsHuZk+ytf6hvkgrY=", "payment_method"=>{"type"=>"Spree::Gateway::StripeGateway", "environment"=>"development", "display_on"=>"", "active"=>"true", "name"=>"Stripe Test", "description"=>""}, "gateway_stripe_gateway"=>{"preferred_login"=>"sk_test_56hUwRKz8MexcGBYpDY5z2Kw", "preferred_currency"=>"AUD", "preferred_server"=>"test", "preferred_test_mode"=>"1"}, "button"=>"", "id"=>"6"}
  [1m[36mSpree::User Load (0.4ms)[0m  [1mSELECT "spree_users".* FROM "spree_users" WHERE "spree_users"."id" = 1 ORDER BY "spree_users"."id" ASC LIMIT 1[0m
  [1m[35mSpree::Preference Load (0.2ms)[0m  SELECT "spree_preferences".* FROM "spree_preferences" WHERE "spree_preferences"."key" = '/spree/backend_configuration/locale' LIMIT 1
  [1m[36m (0.1ms)[0m  [1mSELECT COUNT(*) FROM "spree_roles" INNER JOIN "spree_roles_users" ON "spree_roles"."id" = "spree_roles_users"."role_id" WHERE "spree_roles_users"."user_id" = ? AND "spree_roles"."name" = 'admin'[0m  [["user_id", 1]]
  [1m[35mSpree::PaymentMethod Load (0.1ms)[0m  SELECT "spree_payment_methods".* FROM "spree_payment_methods" WHERE "spree_payment_methods"."deleted_at" IS NULL AND "spree_payment_methods"."id" = ? LIMIT 1  [["id", "6"]]
  [1m[36m (0.1ms)[0m  [1mbegin transaction[0m
  [1m[35mSpree::Preference Load (0.2ms)[0m  SELECT "spree_preferences".* FROM "spree_preferences" WHERE "spree_preferences"."key" = '/spree/gateway/stripe_gateway/login/6' ORDER BY "spree_preferences"."id" ASC LIMIT 1
  [1m[36mSQL (0.8ms)[0m  [1mUPDATE "spree_preferences" SET "value" = ?, "value_type" = ?, "updated_at" = ? WHERE "spree_preferences"."id" = 12[0m  [["value", "--- sk_test_56hUwRKz8MexcGBYpDY5z2Kw\n...\n"], ["value_type", :string], ["updated_at", Sun, 06 Oct 2013 05:27:09 UTC +00:00]]
  [1m[35mSpree::Preference Load (0.2ms)[0m  SELECT "spree_preferences".* FROM "spree_preferences" WHERE "spree_preferences"."key" = '/spree/gateway/stripe_gateway/currency/6' ORDER BY "spree_preferences"."id" ASC LIMIT 1
  [1m[36mSQL (0.1ms)[0m  [1mUPDATE "spree_preferences" SET "value_type" = ?, "updated_at" = ?, "value" = ? WHERE "spree_preferences"."id" = 13[0m  [["value_type", :string], ["updated_at", Sun, 06 Oct 2013 05:27:09 UTC +00:00], ["value", "--- AUD\n...\n"]]
  [1m[35mSpree::Preference Load (0.2ms)[0m  SELECT "spree_preferences".* FROM "spree_preferences" WHERE "spree_preferences"."key" = '/spree/gateway/stripe_gateway/server/6' ORDER BY "spree_preferences"."id" ASC LIMIT 1
  [1m[36mSQL (0.2ms)[0m  [1mUPDATE "spree_preferences" SET "value_type" = ?, "updated_at" = ?, "value" = ? WHERE "spree_preferences"."id" = 14[0m  [["value_type", :string], ["updated_at", Sun, 06 Oct 2013 05:27:09 UTC +00:00], ["value", "--- test\n...\n"]]
  [1m[35mSpree::Preference Load (0.2ms)[0m  SELECT "spree_preferences".* FROM "spree_preferences" WHERE "spree_preferences"."key" = '/spree/gateway/stripe_gateway/test_mode/6' ORDER BY "spree_preferences"."id" ASC LIMIT 1
  [1m[36mSQL (0.2ms)[0m  [1mUPDATE "spree_preferences" SET "value_type" = ?, "updated_at" = ?, "value" = ? WHERE "spree_preferences"."id" = 15[0m  [["value_type", :boolean], ["updated_at", Sun, 06 Oct 2013 05:27:09 UTC +00:00], ["value", "--- true\n...\n"]]
  [1m[35m (3.0ms)[0m  commit transaction
Redirected to http://0.0.0.0:3000/admin/payment_methods/6/edit
Completed 302 Found in 31ms (ActiveRecord: 6.0ms)


Started GET "/admin/payment_methods/6/edit" for 127.0.0.1 at 2013-10-06 16:27:09 +1100
Processing by Spree::Admin::PaymentMethodsController#edit as HTML
  Parameters: {"id"=>"6"}
  [1m[36mSpree::User Load (0.3ms)[0m  [1mSELECT "spree_users".* FROM "spree_users" WHERE "spree_users"."id" = 1 ORDER BY "spree_users"."id" ASC LIMIT 1[0m
  [1m[35mSpree::Preference Load (0.2ms)[0m  SELECT "spree_preferences".* FROM "spree_preferences" WHERE "spree_preferences"."key" = '/spree/backend_configuration/locale' LIMIT 1
  [1m[36m (0.1ms)[0m  [1mSELECT COUNT(*) FROM "spree_roles" INNER JOIN "spree_roles_users" ON "spree_roles"."id" = "spree_roles_users"."role_id" WHERE "spree_roles_users"."user_id" = ? AND "spree_roles"."name" = 'admin'[0m  [["user_id", 1]]
  [1m[35mSpree::PaymentMethod Load (0.1ms)[0m  SELECT "spree_payment_methods".* FROM "spree_payment_methods" WHERE "spree_payment_methods"."deleted_at" IS NULL AND "spree_payment_methods"."id" = ? LIMIT 1  [["id", "6"]]
  Rendered /usr/local/rvm/gems/ruby-2.0.0-p247@spreescratch/gems/spree_backend-2.1.1/app/views/spree/admin/shared/_configuration_menu.html.erb (9.0ms)
  Rendered /usr/local/rvm/gems/ruby-2.0.0-p247@spreescratch/gems/spree_core-2.1.1/app/views/spree/shared/_error_messages.html.erb (0.3ms)
  Rendered /usr/local/rvm/gems/ruby-2.0.0-p247@spreescratch/gems/spree_backend-2.1.1/app/views/spree/admin/payment_methods/_form.html.erb (7.9ms)
  Rendered /usr/local/rvm/gems/ruby-2.0.0-p247@spreescratch/gems/spree_backend-2.1.1/app/views/spree/admin/payment_methods/edit.html.erb within spree/layouts/admin (34.3ms)
  Rendered /usr/local/rvm/gems/ruby-2.0.0-p247@spreescratch/gems/spree_backend-2.1.1/app/views/spree/admin/shared/_translations.html.erb (2.0ms)
  Rendered /usr/local/rvm/gems/ruby-2.0.0-p247@spreescratch/gems/spree_core-2.1.1/app/views/spree/shared/_routes.html.erb (0.6ms)
  Rendered /usr/local/rvm/gems/ruby-2.0.0-p247@spreescratch/gems/spree_backend-2.1.1/app/views/spree/admin/shared/_routes.html.erb (9.3ms)
  Rendered /usr/local/rvm/gems/ruby-2.0.0-p247@spreescratch/gems/spree_backend-2.1.1/app/views/spree/admin/shared/_head.html.erb (49.8ms)
  Rendered /usr/local/rvm/gems/ruby-2.0.0-p247@spreescratch/gems/spree_backend-2.1.1/app/views/spree/admin/shared/_alert.html.erb (0.0ms)
[1;32mDeface:[0m 1 overrides found for 'spree/admin/shared/_header'
[1;32mDeface:[0m 'auth_admin_login_navigation_bar' matched 1 times with '[data-hook='admin_login_navigation_bar'], #admin_login_navigation_bar[data-hook]'
[1;32mDeface: [ERROR][0m The original source for 'auth_admin_login_navigation_bar' has changed, this override should be reviewed to ensure it's still valid.
  Rendered /usr/local/rvm/gems/ruby-2.0.0-p247@spreescratch/gems/spree_backend-2.1.1/app/views/spree/admin/shared/_header.html.erb (3.1ms)
[1;32mDeface:[0m 1 overrides found for 'spree/admin/shared/_menu'
[1;32mDeface:[0m 'user_admin_tabs' matched 1 times with '[data-hook='admin_tabs'], #admin_tabs[data-hook]'
[1;32mDeface: [ERROR][0m The original source for 'user_admin_tabs' has changed, this override should be reviewed to ensure it's still valid.
  Rendered /usr/local/rvm/gems/ruby-2.0.0-p247@spreescratch/gems/spree_backend-2.1.1/app/views/spree/admin/shared/_tabs.html.erb (6.8ms)
  Rendered /usr/local/rvm/gems/ruby-2.0.0-p247@spreescratch/gems/spree_backend-2.1.1/app/views/spree/admin/shared/_menu.html.erb (12.3ms)
  Rendered /usr/local/rvm/gems/ruby-2.0.0-p247@spreescratch/gems/spree_backend-2.1.1/app/views/spree/admin/shared/_sub_menu.html.erb (0.3ms)
  Rendered /usr/local/rvm/gems/ruby-2.0.0-p247@spreescratch/gems/spree_backend-2.1.1/app/views/spree/admin/shared/_content_header.html.erb (0.3ms)
  Rendered /usr/local/rvm/gems/ruby-2.0.0-p247@spreescratch/gems/spree_backend-2.1.1/app/views/spree/admin/shared/_table_filter.html.erb (0.4ms)
  Rendered /usr/local/rvm/gems/ruby-2.0.0-p247@spreescratch/gems/spree_backend-2.1.1/app/views/spree/admin/shared/_sidebar.html.erb (0.3ms)
Completed 200 OK in 271ms (Views: 263.9ms | ActiveRecord: 0.6ms)


Started GET "/assets/jquery.alerts/jquery.alerts.css?body=1" for 127.0.0.1 at 2013-10-06 16:27:09 +1100


Started GET "/assets/jquery.alerts/jquery.alerts.spree.css?body=1" for 127.0.0.1 at 2013-10-06 16:27:09 +1100


Started GET "/assets/responsive-tables.css?body=1" for 127.0.0.1 at 2013-10-06 16:27:09 +1100


Started GET "/assets/jquery.ui.core.css?body=1" for 127.0.0.1 at 2013-10-06 16:27:09 +1100


Started GET "/assets/normalize.css?body=1" for 127.0.0.1 at 2013-10-06 16:27:09 +1100


Started GET "/assets/skeleton.css?body=1" for 127.0.0.1 at 2013-10-06 16:27:09 +1100


Started GET "/assets/jquery.ui.theme.css?body=1" for 127.0.0.1 at 2013-10-06 16:27:10 +1100


Started GET "/assets/jquery.ui.datepicker.css?body=1" for 127.0.0.1 at 2013-10-06 16:27:10 +1100


Started GET "/assets/jquery.ui.menu.css?body=1" for 127.0.0.1 at 2013-10-06 16:27:10 +1100


Started GET "/assets/jquery.ui.autocomplete.css?body=1" for 127.0.0.1 at 2013-10-06 16:27:10 +1100


Started GET "/assets/select2.css?body=1" for 127.0.0.1 at 2013-10-06 16:27:10 +1100


Started GET "/assets/jquery.powertip.css?body=1" for 127.0.0.1 at 2013-10-06 16:27:10 +1100


Started GET "/assets/admin/spree_admin.css?body=1" for 127.0.0.1 at 2013-10-06 16:27:10 +1100


Started GET "/assets/admin/spree_backend.css?body=1" for 127.0.0.1 at 2013-10-06 16:27:10 +1100


Started GET "/assets/admin/all.css?body=1" for 127.0.0.1 at 2013-10-06 16:27:10 +1100


Started GET "/assets/jquery.js?body=1" for 127.0.0.1 at 2013-10-06 16:27:10 +1100


Started GET "/assets/jquery_ujs.js?body=1" for 127.0.0.1 at 2013-10-06 16:27:10 +1100


Started GET "/assets/jquery-migrate-1.0.0.js?body=1" for 127.0.0.1 at 2013-10-06 16:27:10 +1100


Started GET "/assets/jquery.ui.core.js?body=1" for 127.0.0.1 at 2013-10-06 16:27:10 +1100


Started GET "/assets/jquery.ui.datepicker.js?body=1" for 127.0.0.1 at 2013-10-06 16:27:10 +1100


Started GET "/assets/jquery.ui.widget.js?body=1" for 127.0.0.1 at 2013-10-06 16:27:10 +1100


Started GET "/assets/jquery.ui.mouse.js?body=1" for 127.0.0.1 at 2013-10-06 16:27:10 +1100


Started GET "/assets/jquery.ui.sortable.js?body=1" for 127.0.0.1 at 2013-10-06 16:27:10 +1100


Started GET "/assets/jquery.ui.position.js?body=1" for 127.0.0.1 at 2013-10-06 16:27:10 +1100


Started GET "/assets/jquery.ui.menu.js?body=1" for 127.0.0.1 at 2013-10-06 16:27:10 +1100


Started GET "/assets/jquery.ui.autocomplete.js?body=1" for 127.0.0.1 at 2013-10-06 16:27:10 +1100


Started GET "/assets/modernizr.js?body=1" for 127.0.0.1 at 2013-10-06 16:27:10 +1100


Started GET "/assets/jquery.cookie.js?body=1" for 127.0.0.1 at 2013-10-06 16:27:10 +1100


Started GET "/assets/jquery.delayedobserver.js?body=1" for 127.0.0.1 at 2013-10-06 16:27:10 +1100


Started GET "/assets/jquery.jstree/jquery.jstree.js?body=1" for 127.0.0.1 at 2013-10-06 16:27:10 +1100


Started GET "/assets/jquery.alerts/jquery.alerts.js?body=1" for 127.0.0.1 at 2013-10-06 16:27:10 +1100


Started GET "/assets/jquery.powertip.js?body=1" for 127.0.0.1 at 2013-10-06 16:27:10 +1100


Started GET "/assets/jquery.vAlign.js?body=1" for 127.0.0.1 at 2013-10-06 16:27:10 +1100


Started GET "/assets/css_browser_selector_dev.js?body=1" for 127.0.0.1 at 2013-10-06 16:27:10 +1100


Started GET "/assets/spin.js?body=1" for 127.0.0.1 at 2013-10-06 16:27:10 +1100


Started GET "/assets/trunk8.js?body=1" for 127.0.0.1 at 2013-10-06 16:27:10 +1100


Started GET "/assets/jquery.adaptivemenu.js?body=1" for 127.0.0.1 at 2013-10-06 16:27:10 +1100


Started GET "/assets/equalize.js?body=1" for 127.0.0.1 at 2013-10-06 16:27:10 +1100


Started GET "/assets/responsive-tables.js?body=1" for 127.0.0.1 at 2013-10-06 16:27:10 +1100


Started GET "/assets/jsuri.js?body=1" for 127.0.0.1 at 2013-10-06 16:27:10 +1100


Started GET "/assets/spree.js?body=1" for 127.0.0.1 at 2013-10-06 16:27:11 +1100


Started GET "/assets/select2.js?body=1" for 127.0.0.1 at 2013-10-06 16:27:11 +1100


Started GET "/assets/admin/spree-select2.js?body=1" for 127.0.0.1 at 2013-10-06 16:27:11 +1100


Started GET "/assets/admin/address_states.js?body=1" for 127.0.0.1 at 2013-10-06 16:27:11 +1100


Started GET "/assets/admin/admin.js?body=1" for 127.0.0.1 at 2013-10-06 16:27:11 +1100


Started GET "/assets/handlebars.js?body=1" for 127.0.0.1 at 2013-10-06 16:27:11 +1100


Started GET "/assets/admin/handlebar_extensions.js?body=1" for 127.0.0.1 at 2013-10-06 16:27:11 +1100


Started GET "/assets/admin/variant_autocomplete.js?body=1" for 127.0.0.1 at 2013-10-06 16:27:11 +1100


Started GET "/assets/admin/taxon_autocomplete.js?body=1" for 127.0.0.1 at 2013-10-06 16:27:11 +1100


Started GET "/assets/admin/option_type_autocomplete.js?body=1" for 127.0.0.1 at 2013-10-06 16:27:11 +1100


Started GET "/assets/admin/user_picker.js?body=1" for 127.0.0.1 at 2013-10-06 16:27:11 +1100


Started GET "/assets/admin/product_picker.js?body=1" for 127.0.0.1 at 2013-10-06 16:27:11 +1100


Started GET "/assets/admin/calculator.js?body=1" for 127.0.0.1 at 2013-10-06 16:27:11 +1100


Started GET "/assets/admin/checkouts/edit.js?body=1" for 127.0.0.1 at 2013-10-06 16:27:11 +1100


Started GET "/assets/jquery.payment.js?body=1" for 127.0.0.1 at 2013-10-06 16:27:11 +1100


Started GET "/assets/admin/gateway.js?body=1" for 127.0.0.1 at 2013-10-06 16:27:11 +1100


Started GET "/assets/admin/image_settings.js?body=1" for 127.0.0.1 at 2013-10-06 16:27:11 +1100


Started GET "/assets/admin/images/index.js?body=1" for 127.0.0.1 at 2013-10-06 16:27:11 +1100


Started GET "/assets/admin/images/new.js?body=1" for 127.0.0.1 at 2013-10-06 16:27:11 +1100


Started GET "/assets/admin/nested-attribute.js?body=1" for 127.0.0.1 at 2013-10-06 16:27:11 +1100


Started GET "/assets/admin/orders/edit_form.js?body=1" for 127.0.0.1 at 2013-10-06 16:27:11 +1100


Started GET "/assets/admin/orders/edit.js?body=1" for 127.0.0.1 at 2013-10-06 16:27:11 +1100


Started GET "/assets/admin/payments/new.js?body=1" for 127.0.0.1 at 2013-10-06 16:27:11 +1100


Started GET "/assets/admin/progress.js?body=1" for 127.0.0.1 at 2013-10-06 16:27:11 +1100


Started GET "/assets/admin/promotions.js?body=1" for 127.0.0.1 at 2013-10-06 16:27:11 +1100


Started GET "/assets/admin/shipments.js?body=1" for 127.0.0.1 at 2013-10-06 16:27:11 +1100


Started GET "/assets/admin/states.js?body=1" for 127.0.0.1 at 2013-10-06 16:27:11 +1100


Started GET "/assets/admin/stock_management.js?body=1" for 127.0.0.1 at 2013-10-06 16:27:11 +1100


Started GET "/assets/admin/stock_transfer.js?body=1" for 127.0.0.1 at 2013-10-06 16:27:11 +1100


Started GET "/assets/admin/taxon_tree_menu.js?body=1" for 127.0.0.1 at 2013-10-06 16:27:11 +1100


Started GET "/assets/admin/taxonomy.js?body=1" for 127.0.0.1 at 2013-10-06 16:27:11 +1100


Started GET "/assets/admin/underscore-min.js?body=1" for 127.0.0.1 at 2013-10-06 16:27:11 +1100


Started GET "/assets/admin/zone.js?body=1" for 127.0.0.1 at 2013-10-06 16:27:11 +1100


Started GET "/assets/admin/spree_backend.js?body=1" for 127.0.0.1 at 2013-10-06 16:27:11 +1100


Started GET "/assets/admin/all.js?body=1" for 127.0.0.1 at 2013-10-06 16:27:12 +1100


Started GET "/assets/logo/spree_50.png" for 127.0.0.1 at 2013-10-06 16:27:12 +1100


Started PATCH "/checkout/update/payment" for 127.0.0.1 at 2013-10-06 16:27:28 +1100
Processing by Spree::CheckoutController#update as HTML
  Parameters: {"utf8"=>"✓", "authenticity_token"=>"ULTMChoByuqOylMyc2kVfmDUPIWsHuZk+ytf6hvkgrY=", "order"=>{"payments_attributes"=>[{"payment_method_id"=>"6"}]}, "payment_source"=>{"6"=>{"number"=>"[FILTERED]", "expiry"=>"01 / 14", "verification_value"=>"[FILTERED]", "cc_type"=>"visa", "first_name"=>"Victor", "last_name"=>"Ramanauskas"}}, "state"=>"payment"}
  [1m[36mSpree::User Load (0.3ms)[0m  [1mSELECT "spree_users".* FROM "spree_users" WHERE "spree_users"."id" = 1 ORDER BY "spree_users"."id" ASC LIMIT 1[0m
  [1m[35mSpree::Preference Load (0.2ms)[0m  SELECT "spree_preferences".* FROM "spree_preferences" WHERE "spree_preferences"."key" = '/spree/frontend_configuration/locale' LIMIT 1
  [1m[36mSpree::Order Load (0.3ms)[0m  [1mSELECT "spree_orders".* FROM "spree_orders" WHERE "spree_orders"."user_id" = ? AND "spree_orders"."completed_at" IS NULL AND "spree_orders"."created_by_id" = 1 ORDER BY created_at DESC LIMIT 1[0m  [["user_id", 1]]
  [1m[35mSpree::Order Load (0.3ms)[0m  SELECT "spree_orders".* FROM "spree_orders" WHERE "spree_orders"."id" = 3 AND "spree_orders"."currency" = 'USD' LIMIT 1
  [1m[36mSpree::Adjustment Load (0.4ms)[0m  [1mSELECT "spree_adjustments".* FROM "spree_adjustments" WHERE "spree_adjustments"."adjustable_type" = 'Spree::Order' AND "spree_adjustments"."adjustable_id" IN (3) ORDER BY spree_adjustments.created_at ASC[0m
  [1m[35mSpree::Payment Load (0.1ms)[0m  SELECT "spree_payments".* FROM "spree_payments" WHERE "spree_payments"."order_id" = ? AND "spree_payments"."state" = 'completed'  [["order_id", 3]]
  [1m[36mSpree::LineItem Load (0.3ms)[0m  [1mSELECT "spree_line_items".* FROM "spree_line_items" WHERE "spree_line_items"."order_id" = ? ORDER BY created_at ASC[0m  [["order_id", 3]]
  [1m[35mSpree::Adjustment Load (0.3ms)[0m  SELECT "spree_adjustments".* FROM "spree_adjustments" WHERE "spree_adjustments"."adjustable_id" = ? AND "spree_adjustments"."adjustable_type" = ? AND "spree_adjustments"."eligible" = 't' ORDER BY spree_adjustments.created_at ASC  [["adjustable_id", 3], ["adjustable_type", "Spree::Order"]]
  [1m[36mSpree::Payment Load (0.2ms)[0m  [1mSELECT "spree_payments".* FROM "spree_payments" WHERE "spree_payments"."order_id" = ?[0m  [["order_id", 3]]
  [1m[35mCACHE (0.0ms)[0m  SELECT "spree_payments".* FROM "spree_payments" WHERE "spree_payments"."order_id" = ? AND "spree_payments"."state" = 'completed'  [["order_id", 3]]
  [1m[36mCACHE (0.0ms)[0m  [1mSELECT "spree_adjustments".* FROM "spree_adjustments" WHERE "spree_adjustments"."adjustable_id" = ? AND "spree_adjustments"."adjustable_type" = ? AND "spree_adjustments"."eligible" = 't' ORDER BY spree_adjustments.created_at ASC[0m  [["adjustable_id", 3], ["adjustable_type", "Spree::Order"]]
  [1m[35mCACHE (0.0ms)[0m  SELECT "spree_payments".* FROM "spree_payments" WHERE "spree_payments"."order_id" = ? AND "spree_payments"."state" = 'completed'  [["order_id", 3]]
  [1m[36mCACHE (0.0ms)[0m  [1mSELECT "spree_adjustments".* FROM "spree_adjustments" WHERE "spree_adjustments"."adjustable_id" = ? AND "spree_adjustments"."adjustable_type" = ? AND "spree_adjustments"."eligible" = 't' ORDER BY spree_adjustments.created_at ASC[0m  [["adjustable_id", 3], ["adjustable_type", "Spree::Order"]]
  [1m[35mCACHE (0.0ms)[0m  SELECT "spree_payments".* FROM "spree_payments" WHERE "spree_payments"."order_id" = ? AND "spree_payments"."state" = 'completed'  [["order_id", 3]]
  [1m[36mCACHE (0.0ms)[0m  [1mSELECT "spree_adjustments".* FROM "spree_adjustments" WHERE "spree_adjustments"."adjustable_id" = ? AND "spree_adjustments"."adjustable_type" = ? AND "spree_adjustments"."eligible" = 't' ORDER BY spree_adjustments.created_at ASC[0m  [["adjustable_id", 3], ["adjustable_type", "Spree::Order"]]
  [1m[35m (0.2ms)[0m  SELECT COUNT(*) FROM "spree_line_items" WHERE "spree_line_items"."order_id" = ?  [["order_id", 3]]
  [1m[36mSpree::StockItem Load (0.2ms)[0m  [1mSELECT "spree_stock_items".* FROM "spree_stock_items" INNER JOIN "spree_stock_locations" ON "spree_stock_locations"."id" = "spree_stock_items"."stock_location_id" WHERE "spree_stock_items"."deleted_at" IS NULL AND "spree_stock_items"."variant_id" = 7 AND "spree_stock_locations"."active" = 't'[0m
  [1m[35mCACHE (0.0ms)[0m  SELECT "spree_payments".* FROM "spree_payments" WHERE "spree_payments"."order_id" = ? AND "spree_payments"."state" = 'completed'  [["order_id", 3]]
  [1m[36mCACHE (0.0ms)[0m  [1mSELECT "spree_adjustments".* FROM "spree_adjustments" WHERE "spree_adjustments"."adjustable_id" = ? AND "spree_adjustments"."adjustable_type" = ? AND "spree_adjustments"."eligible" = 't' ORDER BY spree_adjustments.created_at ASC[0m  [["adjustable_id", 3], ["adjustable_type", "Spree::Order"]]
  [1m[35mSpree::User Load (0.1ms)[0m  SELECT "spree_users".* FROM "spree_users" WHERE "spree_users"."id" = ? ORDER BY "spree_users"."id" ASC LIMIT 1  [["id", 1]]
  [1m[36mCACHE (0.0ms)[0m  [1mSELECT "spree_payments".* FROM "spree_payments" WHERE "spree_payments"."order_id" = ? AND "spree_payments"."state" = 'completed'[0m  [["order_id", 3]]
  [1m[35mCACHE (0.0ms)[0m  SELECT "spree_adjustments".* FROM "spree_adjustments" WHERE "spree_adjustments"."adjustable_id" = ? AND "spree_adjustments"."adjustable_type" = ? AND "spree_adjustments"."eligible" = 't' ORDER BY spree_adjustments.created_at ASC  [["adjustable_id", 3], ["adjustable_type", "Spree::Order"]]
  [1m[36mSpree::Shipment Load (0.2ms)[0m  [1mSELECT "spree_shipments".* FROM "spree_shipments" WHERE "spree_shipments"."order_id" = ?[0m  [["order_id", 3]]
  [1m[35mSpree::StockLocation Load (0.1ms)[0m  SELECT "spree_stock_locations".* FROM "spree_stock_locations" WHERE "spree_stock_locations"."id" = ? ORDER BY "spree_stock_locations"."id" ASC LIMIT 1  [["id", 1]]
  [1m[36mSpree::Order Load (0.1ms)[0m  [1mSELECT "spree_orders".* FROM "spree_orders" WHERE "spree_orders"."id" = ? ORDER BY "spree_orders"."id" ASC LIMIT 1[0m  [["id", 3]]
  [1m[35mSpree::InventoryUnit Load (0.1ms)[0m  SELECT "spree_inventory_units".* FROM "spree_inventory_units" WHERE "spree_inventory_units"."shipment_id" = ?  [["shipment_id", 3]]
  [1m[36mSpree::Variant Load (0.3ms)[0m  [1mSELECT "spree_variants".* FROM "spree_variants" WHERE "spree_variants"."deleted_at" IS NULL AND "spree_variants"."id" IN (7)[0m
  [1m[35mSpree::Variant Load (0.1ms)[0m  SELECT "spree_variants".* FROM "spree_variants" WHERE "spree_variants"."id" = ? ORDER BY "spree_variants"."id" ASC LIMIT 1  [["id", 7]]
  [1m[36m (0.1ms)[0m  [1mSELECT COUNT(*) FROM "spree_roles" INNER JOIN "spree_roles_users" ON "spree_roles"."id" = "spree_roles_users"."role_id" WHERE "spree_roles_users"."user_id" = ? AND "spree_roles"."name" = 'admin'[0m  [["user_id", 1]]
  [1m[35mCACHE (0.0ms)[0m  SELECT "spree_payments".* FROM "spree_payments" WHERE "spree_payments"."order_id" = ? AND "spree_payments"."state" = 'completed'  [["order_id", 3]]
  [1m[36mCACHE (0.0ms)[0m  [1mSELECT "spree_adjustments".* FROM "spree_adjustments" WHERE "spree_adjustments"."adjustable_id" = ? AND "spree_adjustments"."adjustable_type" = ? AND "spree_adjustments"."eligible" = 't' ORDER BY spree_adjustments.created_at ASC[0m  [["adjustable_id", 3], ["adjustable_type", "Spree::Order"]]
  [1m[35m (0.1ms)[0m  begin transaction
  [1m[36mSpree::PaymentMethod Load (0.1ms)[0m  [1mSELECT "spree_payment_methods".* FROM "spree_payment_methods" WHERE "spree_payment_methods"."deleted_at" IS NULL AND "spree_payment_methods"."id" = ? ORDER BY "spree_payment_methods"."id" ASC LIMIT 1[0m  [["id", 6]]
  [1m[35mCACHE (0.0ms)[0m  SELECT "spree_payments".* FROM "spree_payments" WHERE "spree_payments"."order_id" = ? AND "spree_payments"."state" = 'completed'  [["order_id", 3]]
  [1m[36mCACHE (0.0ms)[0m  [1mSELECT "spree_adjustments".* FROM "spree_adjustments" WHERE "spree_adjustments"."adjustable_id" = ? AND "spree_adjustments"."adjustable_type" = ? AND "spree_adjustments"."eligible" = 't' ORDER BY spree_adjustments.created_at ASC[0m  [["adjustable_id", 3], ["adjustable_type", "Spree::Order"]]
  [1m[35mSQL (0.6ms)[0m  INSERT INTO "spree_credit_cards" ("cc_type", "created_at", "first_name", "last_digits", "last_name", "month", "updated_at", "year") VALUES (?, ?, ?, ?, ?, ?, ?, ?)  [["cc_type", "visa"], ["created_at", Sun, 06 Oct 2013 05:27:28 UTC +00:00], ["first_name", "Victor"], ["last_digits", "4242"], ["last_name", "Ramanauskas"], ["month", "01"], ["updated_at", Sun, 06 Oct 2013 05:27:28 UTC +00:00], ["year", "2014"]]
  [1m[36mSpree::Payment Exists (0.2ms)[0m  [1mSELECT 1 AS one FROM "spree_payments" WHERE "spree_payments"."identifier" = 'P5GK5QJP' LIMIT 1[0m
  [1m[35mSQL (0.4ms)[0m  INSERT INTO "spree_payments" ("amount", "created_at", "identifier", "order_id", "payment_method_id", "source_id", "source_type", "state", "updated_at") VALUES (?, ?, ?, ?, ?, ?, ?, ?, ?)  [["amount", #<BigDecimal:7f7fa571d3c0,'0.1999E2',18(36)>], ["created_at", Sun, 06 Oct 2013 05:27:28 UTC +00:00], ["identifier", "P5GK5QJP"], ["order_id", 3], ["payment_method_id", 6], ["source_id", 2], ["source_type", "Spree::CreditCard"], ["state", "checkout"], ["updated_at", Sun, 06 Oct 2013 05:27:28 UTC +00:00]]
  [1m[36mSpree::Order Load (0.1ms)[0m  [1mSELECT "spree_orders".* FROM "spree_orders" WHERE "spree_orders"."id" = ? ORDER BY "spree_orders"."id" ASC LIMIT 1[0m  [["id", 3]]
  [1m[35mSpree::Payment Load (0.1ms)[0m  SELECT "spree_payments".* FROM "spree_payments" WHERE "spree_payments"."order_id" = ? AND "spree_payments"."state" = 'checkout' AND (id != 3)  [["order_id", 3]]
  [1m[36mSpree::Address Load (0.1ms)[0m  [1mSELECT "spree_addresses".* FROM "spree_addresses" WHERE "spree_addresses"."id" = ? ORDER BY "spree_addresses"."id" ASC LIMIT 1[0m  [["id", 3]]
  [1m[35mSpree::Country Load (0.1ms)[0m  SELECT "spree_countries".* FROM "spree_countries" WHERE "spree_countries"."id" = ? ORDER BY "spree_countries"."id" ASC LIMIT 1  [["id", 109]]
  [1m[36mSQL (0.3ms)[0m  [1mUPDATE "spree_credit_cards" SET "gateway_customer_profile_id" = ?, "updated_at" = ? WHERE "spree_credit_cards"."id" = 2[0m  [["gateway_customer_profile_id", "cus_2hZDbpx0golrRG"], ["updated_at", Sun, 06 Oct 2013 05:27:31 UTC +00:00]]
  [1m[35mSpree::Payment Load (0.1ms)[0m  SELECT "spree_payments".* FROM "spree_payments" WHERE "spree_payments"."order_id" = ?  [["order_id", 3]]
  [1m[36mSpree::Payment Load (0.1ms)[0m  [1mSELECT "spree_payments".* FROM "spree_payments" WHERE "spree_payments"."order_id" = ? AND "spree_payments"."state" = 'completed'[0m  [["order_id", 3]]
  [1m[35mSpree::LineItem Load (0.2ms)[0m  SELECT "spree_line_items".* FROM "spree_line_items" WHERE "spree_line_items"."order_id" = ? ORDER BY created_at ASC  [["order_id", 3]]
  [1m[36mSpree::Adjustment Load (0.2ms)[0m  [1mSELECT "spree_adjustments".* FROM "spree_adjustments" WHERE "spree_adjustments"."adjustable_id" = ? AND "spree_adjustments"."adjustable_type" = ? AND "spree_adjustments"."eligible" = 't' ORDER BY spree_adjustments.created_at ASC[0m  [["adjustable_id", 3], ["adjustable_type", "Spree::Order"]]
  [1m[35mSpree::Adjustment Load (0.2ms)[0m  SELECT "spree_adjustments".* FROM "spree_adjustments" WHERE "spree_adjustments"."adjustable_id" = ? AND "spree_adjustments"."adjustable_type" = ? ORDER BY spree_adjustments.created_at ASC  [["adjustable_id", 3], ["adjustable_type", "Spree::Order"]]
  [1m[36mSpree::Adjustment Load (0.1ms)[0m  [1mSELECT "spree_adjustments".* FROM "spree_adjustments" WHERE "spree_adjustments"."adjustable_id" = ? AND "spree_adjustments"."adjustable_type" = ? AND "spree_adjustments"."originator_type" = 'Spree::PromotionAction' ORDER BY spree_adjustments.created_at ASC[0m  [["adjustable_id", 3], ["adjustable_type", "Spree::Order"]]
  [1m[35mSpree::Adjustment Load (0.1ms)[0m  SELECT "spree_adjustments".* FROM "spree_adjustments" WHERE "spree_adjustments"."adjustable_id" = ? AND "spree_adjustments"."adjustable_type" = ? AND "spree_adjustments"."originator_type" = 'Spree::PromotionAction' AND "spree_adjustments"."eligible" = 't' ORDER BY amount ASC, created_at DESC LIMIT 1  [["adjustable_id", 3], ["adjustable_type", "Spree::Order"]]
  [1m[36mCACHE (0.0ms)[0m  [1mSELECT "spree_adjustments".* FROM "spree_adjustments" WHERE "spree_adjustments"."adjustable_id" = ? AND "spree_adjustments"."adjustable_type" = ? ORDER BY spree_adjustments.created_at ASC[0m  [["adjustable_id", 3], ["adjustable_type", "Spree::Order"]]
  [1m[35mSpree::Adjustment Load (0.1ms)[0m  SELECT "spree_adjustments".* FROM "spree_adjustments" WHERE "spree_adjustments"."adjustable_id" = ? AND "spree_adjustments"."adjustable_type" = ? AND "spree_adjustments"."originator_type" = 'Spree::ShippingMethod' ORDER BY spree_adjustments.created_at ASC  [["adjustable_id", 3], ["adjustable_type", "Spree::Order"]]
  [1m[36mSpree::Adjustment Load (0.0ms)[0m  [1mSELECT "spree_adjustments".* FROM "spree_adjustments" WHERE "spree_adjustments"."id" = ? LIMIT 1[0m  [["id", 9]]
  [1m[35mSpree::ShippingMethod Load (0.1ms)[0m  SELECT "spree_shipping_methods".* FROM "spree_shipping_methods" WHERE "spree_shipping_methods"."deleted_at" IS NULL AND "spree_shipping_methods"."id" = ? ORDER BY "spree_shipping_methods"."id" ASC LIMIT 1  [["id", 5]]
  [1m[36mSpree::Shipment Load (0.1ms)[0m  [1mSELECT "spree_shipments".* FROM "spree_shipments" WHERE "spree_shipments"."id" = ? ORDER BY "spree_shipments"."id" ASC LIMIT 1[0m  [["id", 3]]
  [1m[35mSpree::StockLocation Load (0.1ms)[0m  SELECT "spree_stock_locations".* FROM "spree_stock_locations" WHERE "spree_stock_locations"."id" = ? ORDER BY "spree_stock_locations"."id" ASC LIMIT 1  [["id", 1]]
  [1m[36mSpree::Order Load (0.1ms)[0m  [1mSELECT "spree_orders".* FROM "spree_orders" WHERE "spree_orders"."id" = ? ORDER BY "spree_orders"."id" ASC LIMIT 1[0m  [["id", 3]]
  [1m[35mSpree::InventoryUnit Load (0.1ms)[0m  SELECT "spree_inventory_units".* FROM "spree_inventory_units" WHERE "spree_inventory_units"."shipment_id" = ?  [["shipment_id", 3]]
  [1m[36mSpree::Variant Load (0.2ms)[0m  [1mSELECT "spree_variants".* FROM "spree_variants" WHERE "spree_variants"."deleted_at" IS NULL AND "spree_variants"."id" IN (7)[0m
  [1m[35mSpree::Calculator Load (0.1ms)[0m  SELECT "spree_calculators".* FROM "spree_calculators" WHERE "spree_calculators"."calculable_id" = ? AND "spree_calculators"."calculable_type" = ? ORDER BY "spree_calculators"."id" ASC LIMIT 1  [["calculable_id", 5], ["calculable_type", "Spree::ShippingMethod"]]
  [1m[36mSpree::Price Load (0.1ms)[0m  [1mSELECT "spree_prices".* FROM "spree_prices" WHERE "spree_prices"."variant_id" = ? AND "spree_prices"."currency" = 'USD' ORDER BY "spree_prices"."id" ASC LIMIT 1[0m  [["variant_id", 7]]
  [1m[35mSQL (0.2ms)[0m  UPDATE "spree_adjustments" SET "amount" = 0.0 WHERE "spree_adjustments"."id" = 9
  [1m[36mSQL (0.1ms)[0m  [1mUPDATE "spree_adjustments" SET "eligible" = 't' WHERE "spree_adjustments"."id" = 9[0m
  [1m[35mSpree::Payment Load (0.1ms)[0m  SELECT "spree_payments".* FROM "spree_payments" WHERE "spree_payments"."order_id" = ? AND "spree_payments"."state" = 'completed'  [["order_id", 3]]
  [1m[36mSpree::Adjustment Load (0.1ms)[0m  [1mSELECT "spree_adjustments".* FROM "spree_adjustments" WHERE "spree_adjustments"."adjustable_id" = ? AND "spree_adjustments"."adjustable_type" = ? AND "spree_adjustments"."eligible" = 't' ORDER BY spree_adjustments.created_at ASC[0m  [["adjustable_id", 3], ["adjustable_type", "Spree::Order"]]
  [1m[35mSQL (0.1ms)[0m  UPDATE "spree_orders" SET "payment_state" = NULL, "shipment_state" = NULL, "item_total" = 19.99, "adjustment_total" = 0.0, "payment_total" = 0.0, "total" = 19.99 WHERE "spree_orders"."id" = 3
  [1m[36m (5.3ms)[0m  [1mcommit transaction[0m
  [1m[35m (0.1ms)[0m  begin transaction
  [1m[36mSpree::Payment Load (0.2ms)[0m  [1mSELECT "spree_payments".* FROM "spree_payments" WHERE "spree_payments"."order_id" = ? AND "spree_payments"."state" = 'completed'[0m  [["order_id", 3]]
  [1m[35mSpree::Adjustment Load (0.2ms)[0m  SELECT "spree_adjustments".* FROM "spree_adjustments" WHERE "spree_adjustments"."adjustable_id" = ? AND "spree_adjustments"."adjustable_type" = ? AND "spree_adjustments"."eligible" = 't' ORDER BY spree_adjustments.created_at ASC  [["adjustable_id", 3], ["adjustable_type", "Spree::Order"]]
  [1m[36mSQL (0.3ms)[0m  [1mUPDATE "spree_orders" SET "state" = ?, "updated_at" = ? WHERE "spree_orders"."id" = 3[0m  [["state", "confirm"], ["updated_at", Sun, 06 Oct 2013 05:27:31 UTC +00:00]]
  [1m[35mSpree::Payment Load (0.1ms)[0m  SELECT "spree_payments".* FROM "spree_payments" WHERE "spree_payments"."order_id" = ? AND "spree_payments"."state" = 'completed'  [["order_id", 3]]
  [1m[36mSpree::Adjustment Load (0.2ms)[0m  [1mSELECT "spree_adjustments".* FROM "spree_adjustments" WHERE "spree_adjustments"."adjustable_id" = ? AND "spree_adjustments"."adjustable_type" = ? AND "spree_adjustments"."eligible" = 't' ORDER BY spree_adjustments.created_at ASC[0m  [["adjustable_id", 3], ["adjustable_type", "Spree::Order"]]
  [1m[35m (2.5ms)[0m  commit transaction
Redirected to http://0.0.0.0:3000/checkout/confirm
Completed 302 Found in 2399ms (ActiveRecord: 17.5ms)


Started GET "/checkout/confirm" for 127.0.0.1 at 2013-10-06 16:27:31 +1100
Processing by Spree::CheckoutController#edit as HTML
  Parameters: {"state"=>"confirm"}
  [1m[36mSpree::User Load (0.3ms)[0m  [1mSELECT "spree_users".* FROM "spree_users" WHERE "spree_users"."id" = 1 ORDER BY "spree_users"."id" ASC LIMIT 1[0m
  [1m[35mSpree::Preference Load (0.2ms)[0m  SELECT "spree_preferences".* FROM "spree_preferences" WHERE "spree_preferences"."key" = '/spree/frontend_configuration/locale' LIMIT 1
  [1m[36mSpree::Order Load (0.2ms)[0m  [1mSELECT "spree_orders".* FROM "spree_orders" WHERE "spree_orders"."user_id" = ? AND "spree_orders"."completed_at" IS NULL AND "spree_orders"."created_by_id" = 1 ORDER BY created_at DESC LIMIT 1[0m  [["user_id", 1]]
  [1m[35mSpree::Order Load (0.2ms)[0m  SELECT "spree_orders".* FROM "spree_orders" WHERE "spree_orders"."id" = 3 AND "spree_orders"."currency" = 'USD' LIMIT 1
  [1m[36mSpree::Adjustment Load (0.4ms)[0m  [1mSELECT "spree_adjustments".* FROM "spree_adjustments" WHERE "spree_adjustments"."adjustable_type" = 'Spree::Order' AND "spree_adjustments"."adjustable_id" IN (3) ORDER BY spree_adjustments.created_at ASC[0m
  [1m[35mSpree::Payment Load (0.1ms)[0m  SELECT "spree_payments".* FROM "spree_payments" WHERE "spree_payments"."order_id" = ? AND "spree_payments"."state" = 'completed'  [["order_id", 3]]
  [1m[36mSpree::LineItem Load (0.2ms)[0m  [1mSELECT "spree_line_items".* FROM "spree_line_items" WHERE "spree_line_items"."order_id" = ? ORDER BY created_at ASC[0m  [["order_id", 3]]
  [1m[35mSpree::Adjustment Load (0.2ms)[0m  SELECT "spree_adjustments".* FROM "spree_adjustments" WHERE "spree_adjustments"."adjustable_id" = ? AND "spree_adjustments"."adjustable_type" = ? AND "spree_adjustments"."eligible" = 't' ORDER BY spree_adjustments.created_at ASC  [["adjustable_id", 3], ["adjustable_type", "Spree::Order"]]
  [1m[36mSpree::Payment Load (0.1ms)[0m  [1mSELECT "spree_payments".* FROM "spree_payments" WHERE "spree_payments"."order_id" = ?[0m  [["order_id", 3]]
  [1m[35mSpree::PaymentMethod Load (0.1ms)[0m  SELECT "spree_payment_methods".* FROM "spree_payment_methods" WHERE "spree_payment_methods"."deleted_at" IS NULL AND "spree_payment_methods"."id" = ? ORDER BY "spree_payment_methods"."id" ASC LIMIT 1  [["id", 6]]
  [1m[36mCACHE (0.0ms)[0m  [1mSELECT "spree_payments".* FROM "spree_payments" WHERE "spree_payments"."order_id" = ? AND "spree_payments"."state" = 'completed'[0m  [["order_id", 3]]
  [1m[35mCACHE (0.0ms)[0m  SELECT "spree_adjustments".* FROM "spree_adjustments" WHERE "spree_adjustments"."adjustable_id" = ? AND "spree_adjustments"."adjustable_type" = ? AND "spree_adjustments"."eligible" = 't' ORDER BY spree_adjustments.created_at ASC  [["adjustable_id", 3], ["adjustable_type", "Spree::Order"]]
  [1m[36mCACHE (0.0ms)[0m  [1mSELECT "spree_payments".* FROM "spree_payments" WHERE "spree_payments"."order_id" = ? AND "spree_payments"."state" = 'completed'[0m  [["order_id", 3]]
  [1m[35mCACHE (0.0ms)[0m  SELECT "spree_adjustments".* FROM "spree_adjustments" WHERE "spree_adjustments"."adjustable_id" = ? AND "spree_adjustments"."adjustable_type" = ? AND "spree_adjustments"."eligible" = 't' ORDER BY spree_adjustments.created_at ASC  [["adjustable_id", 3], ["adjustable_type", "Spree::Order"]]
  [1m[36mCACHE (0.0ms)[0m  [1mSELECT "spree_payments".* FROM "spree_payments" WHERE "spree_payments"."order_id" = ? AND "spree_payments"."state" = 'completed'[0m  [["order_id", 3]]
  [1m[35mCACHE (0.0ms)[0m  SELECT "spree_adjustments".* FROM "spree_adjustments" WHERE "spree_adjustments"."adjustable_id" = ? AND "spree_adjustments"."adjustable_type" = ? AND "spree_adjustments"."eligible" = 't' ORDER BY spree_adjustments.created_at ASC  [["adjustable_id", 3], ["adjustable_type", "Spree::Order"]]
  [1m[36m (0.1ms)[0m  [1mSELECT COUNT(*) FROM "spree_line_items" WHERE "spree_line_items"."order_id" = ?[0m  [["order_id", 3]]
  [1m[35mSpree::StockItem Load (0.2ms)[0m  SELECT "spree_stock_items".* FROM "spree_stock_items" INNER JOIN "spree_stock_locations" ON "spree_stock_locations"."id" = "spree_stock_items"."stock_location_id" WHERE "spree_stock_items"."deleted_at" IS NULL AND "spree_stock_items"."variant_id" = 7 AND "spree_stock_locations"."active" = 't'
  [1m[36mCACHE (0.0ms)[0m  [1mSELECT "spree_payments".* FROM "spree_payments" WHERE "spree_payments"."order_id" = ? AND "spree_payments"."state" = 'completed'[0m  [["order_id", 3]]
  [1m[35mCACHE (0.0ms)[0m  SELECT "spree_adjustments".* FROM "spree_adjustments" WHERE "spree_adjustments"."adjustable_id" = ? AND "spree_adjustments"."adjustable_type" = ? AND "spree_adjustments"."eligible" = 't' ORDER BY spree_adjustments.created_at ASC  [["adjustable_id", 3], ["adjustable_type", "Spree::Order"]]
  [1m[36mSpree::User Load (0.1ms)[0m  [1mSELECT "spree_users".* FROM "spree_users" WHERE "spree_users"."id" = ? ORDER BY "spree_users"."id" ASC LIMIT 1[0m  [["id", 1]]
  [1m[35m (0.1ms)[0m  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" = ? AND "spree_roles"."name" = 'admin'  [["user_id", 1]]
  Rendered /usr/local/rvm/gems/ruby-2.0.0-p247@spreescratch/gems/spree_core-2.1.1/app/views/spree/shared/_error_messages.html.erb (0.4ms)
  [1m[36mCACHE (0.0ms)[0m  [1mSELECT "spree_payments".* FROM "spree_payments" WHERE "spree_payments"."order_id" = ? AND "spree_payments"."state" = 'completed'[0m  [["order_id", 3]]
  [1m[35mCACHE (0.0ms)[0m  SELECT "spree_adjustments".* FROM "spree_adjustments" WHERE "spree_adjustments"."adjustable_id" = ? AND "spree_adjustments"."adjustable_type" = ? AND "spree_adjustments"."eligible" = 't' ORDER BY spree_adjustments.created_at ASC  [["adjustable_id", 3], ["adjustable_type", "Spree::Order"]]
  [1m[36mCACHE (0.0ms)[0m  [1mSELECT "spree_payments".* FROM "spree_payments" WHERE "spree_payments"."order_id" = ? AND "spree_payments"."state" = 'completed'[0m  [["order_id", 3]]
  [1m[35mCACHE (0.0ms)[0m  SELECT "spree_adjustments".* FROM "spree_adjustments" WHERE "spree_adjustments"."adjustable_id" = ? AND "spree_adjustments"."adjustable_type" = ? AND "spree_adjustments"."eligible" = 't' ORDER BY spree_adjustments.created_at ASC  [["adjustable_id", 3], ["adjustable_type", "Spree::Order"]]
  [1m[36mCACHE (0.0ms)[0m  [1mSELECT "spree_payments".* FROM "spree_payments" WHERE "spree_payments"."order_id" = ? AND "spree_payments"."state" = 'completed'[0m  [["order_id", 3]]
  [1m[35mCACHE (0.0ms)[0m  SELECT "spree_adjustments".* FROM "spree_adjustments" WHERE "spree_adjustments"."adjustable_id" = ? AND "spree_adjustments"."adjustable_type" = ? AND "spree_adjustments"."eligible" = 't' ORDER BY spree_adjustments.created_at ASC  [["adjustable_id", 3], ["adjustable_type", "Spree::Order"]]
  [1m[36mSpree::Address Load (0.2ms)[0m  [1mSELECT "spree_addresses".* FROM "spree_addresses" WHERE "spree_addresses"."id" = ? ORDER BY "spree_addresses"."id" ASC LIMIT 1[0m  [["id", 4]]
  [1m[35mSpree::Country Load (0.2ms)[0m  SELECT "spree_countries".* FROM "spree_countries" WHERE "spree_countries"."id" = ? ORDER BY "spree_countries"."id" ASC LIMIT 1  [["id", 109]]
  Rendered /usr/local/rvm/gems/ruby-2.0.0-p247@spreescratch/gems/spree_core-2.1.1/app/views/spree/shared/_address.html.erb (3.0ms)
  [1m[36mSpree::Address Load (0.1ms)[0m  [1mSELECT "spree_addresses".* FROM "spree_addresses" WHERE "spree_addresses"."id" = ? ORDER BY "spree_addresses"."id" ASC LIMIT 1[0m  [["id", 3]]
  [1m[35mCACHE (0.0ms)[0m  SELECT "spree_countries".* FROM "spree_countries" WHERE "spree_countries"."id" = ? ORDER BY "spree_countries"."id" ASC LIMIT 1  [["id", 109]]
  Rendered /usr/local/rvm/gems/ruby-2.0.0-p247@spreescratch/gems/spree_core-2.1.1/app/views/spree/shared/_address.html.erb (2.1ms)
  [1m[36mCACHE (0.0ms)[0m  [1mSELECT "spree_payments".* FROM "spree_payments" WHERE "spree_payments"."order_id" = ? AND "spree_payments"."state" = 'completed'[0m  [["order_id", 3]]
  [1m[35mCACHE (0.0ms)[0m  SELECT "spree_adjustments".* FROM "spree_adjustments" WHERE "spree_adjustments"."adjustable_id" = ? AND "spree_adjustments"."adjustable_type" = ? AND "spree_adjustments"."eligible" = 't' ORDER BY spree_adjustments.created_at ASC  [["adjustable_id", 3], ["adjustable_type", "Spree::Order"]]
  [1m[36mSpree::Shipment Load (0.2ms)[0m  [1mSELECT "spree_shipments".* FROM "spree_shipments" WHERE "spree_shipments"."order_id" = ?[0m  [["order_id", 3]]
  [1m[35mSpree::StockLocation Load (0.2ms)[0m  SELECT "spree_stock_locations".* FROM "spree_stock_locations" WHERE "spree_stock_locations"."id" = ? ORDER BY "spree_stock_locations"."id" ASC LIMIT 1  [["id", 1]]
  [1m[36mSpree::ShippingRate Load (0.3ms)[0m  [1mSELECT "spree_shipping_rates".* FROM "spree_shipping_rates" WHERE "spree_shipping_rates"."shipment_id" = ? AND "spree_shipping_rates"."selected" = 't' ORDER BY "spree_shipping_rates"."id" ASC LIMIT 1[0m  [["shipment_id", 3]]
  [1m[35mSpree::ShippingMethod Load (0.1ms)[0m  SELECT "spree_shipping_methods".* FROM "spree_shipping_methods" WHERE "spree_shipping_methods"."deleted_at" IS NULL AND "spree_shipping_methods"."id" = ? ORDER BY "spree_shipping_methods"."id" ASC LIMIT 1  [["id", 5]]
  [1m[36mSpree::Payment Load (0.4ms)[0m  [1mSELECT "spree_payments".* FROM "spree_payments" WHERE "spree_payments"."order_id" = ? AND (state NOT IN ('failed','invalid'))[0m  [["order_id", 3]]
  [1m[35mSpree::CreditCard Load (0.3ms)[0m  SELECT "spree_credit_cards".* FROM "spree_credit_cards" WHERE "spree_credit_cards"."id" = ? ORDER BY "spree_credit_cards"."id" ASC LIMIT 1  [["id", 2]]
  Rendered /usr/local/rvm/gems/ruby-2.0.0-p247@spreescratch/gems/spree_core-2.1.1/app/views/spree/payments/_payment.html.erb (80.9ms)
  [1m[36mSpree::Variant Load (0.2ms)[0m  [1mSELECT "spree_variants".* FROM "spree_variants" WHERE "spree_variants"."id" = ? ORDER BY "spree_variants"."id" ASC LIMIT 1[0m  [["id", 7]]
  [1m[35mSpree::Image Load (0.3ms)[0m  SELECT "spree_assets".* FROM "spree_assets" WHERE "spree_assets"."type" IN ('Spree::Image') AND "spree_assets"."viewable_id" = ? AND "spree_assets"."viewable_type" = ? ORDER BY "spree_assets".position ASC  [["viewable_id", 7], ["viewable_type", "Spree::Variant"]]
  [1m[36mSpree::Product Load (0.1ms)[0m  [1mSELECT "spree_products".* FROM "spree_products" WHERE "spree_products"."id" = ? ORDER BY "spree_products"."id" ASC LIMIT 1[0m  [["id", 7]]
  [1m[35mSpree::OptionValue Exists (0.3ms)[0m  SELECT 1 AS one FROM "spree_option_values" INNER JOIN "spree_option_values_variants" ON "spree_option_values"."id" = "spree_option_values_variants"."option_value_id" WHERE "spree_option_values_variants"."variant_id" = ? LIMIT 1  [["variant_id", 7]]
  [1m[36mSpree::Adjustment Load (0.2ms)[0m  [1mSELECT "spree_adjustments".* FROM "spree_adjustments" INNER JOIN "spree_line_items" ON "spree_adjustments"."adjustable_id" = "spree_line_items"."id" AND "spree_adjustments"."adjustable_type" = 'Spree::LineItem' WHERE "spree_line_items"."order_id" = ? AND "spree_adjustments"."eligible" = 't' ORDER BY created_at ASC[0m  [["order_id", 3]]
  [1m[35mCACHE (0.0ms)[0m  SELECT "spree_adjustments".* FROM "spree_adjustments" WHERE "spree_adjustments"."adjustable_id" = ? AND "spree_adjustments"."adjustable_type" = ? AND "spree_adjustments"."eligible" = 't' ORDER BY spree_adjustments.created_at ASC  [["adjustable_id", 3], ["adjustable_type", "Spree::Order"]]
  [1m[36mSpree::Order Load (0.1ms)[0m  [1mSELECT "spree_orders".* FROM "spree_orders" WHERE "spree_orders"."id" = ? ORDER BY "spree_orders"."id" ASC LIMIT 1[0m  [["id", 3]]
  Rendered /usr/local/rvm/gems/ruby-2.0.0-p247@spreescratch/gems/spree_frontend-2.1.1/app/views/spree/shared/_order_details.html.erb (166.6ms)
  Rendered /usr/local/rvm/gems/ruby-2.0.0-p247@spreescratch/gems/spree_frontend-2.1.1/app/views/spree/checkout/_confirm.html.erb (213.8ms)
  Rendered /usr/local/rvm/gems/ruby-2.0.0-p247@spreescratch/gems/spree_frontend-2.1.1/app/views/spree/checkout/edit.html.erb within spree/layouts/spree_application (252.5ms)
  Rendered /usr/local/rvm/gems/ruby-2.0.0-p247@spreescratch/gems/spree_core-2.1.1/app/views/spree/shared/_routes.html.erb (0.6ms)
  Rendered /usr/local/rvm/gems/ruby-2.0.0-p247@spreescratch/gems/spree_frontend-2.1.1/app/views/spree/shared/_head.html.erb (12.8ms)
[1;32mDeface:[0m 1 overrides found for 'spree/shared/_nav_bar'
[1;32mDeface:[0m 'auth_shared_login_bar' matched 1 times with 'li#search-bar'
[1;32mDeface: [ERROR][0m The original source for 'auth_shared_login_bar' has changed, this override should be reviewed to ensure it's still valid.
  [1m[35mSpree::Taxon Load (0.4ms)[0m  SELECT "spree_taxons".* FROM "spree_taxons" WHERE "spree_taxons"."parent_id" IS NULL ORDER BY "lft"
  Rendered /usr/local/rvm/gems/ruby-2.0.0-p247@spreescratch/gems/spree_frontend-2.1.1/app/views/spree/shared/_search.html.erb (3.1ms)
  Rendered /usr/local/rvm/gems/ruby-2.0.0-p247@spreescratch/gems/spree_frontend-2.1.1/app/views/spree/shared/_nav_bar.html.erb (8.5ms)
  Rendered /usr/local/rvm/gems/ruby-2.0.0-p247@spreescratch/gems/spree_frontend-2.1.1/app/views/spree/shared/_main_nav_bar.html.erb (2.3ms)
  Rendered /usr/local/rvm/gems/ruby-2.0.0-p247@spreescratch/gems/spree_frontend-2.1.1/app/views/spree/shared/_header.html.erb (27.3ms)
  Rendered /usr/local/rvm/gems/ruby-2.0.0-p247@spreescratch/gems/spree_frontend-2.1.1/app/views/spree/shared/_footer.html.erb (0.4ms)
  [1m[36mSpree::Tracker Load (0.4ms)[0m  [1mSELECT "spree_trackers".* FROM "spree_trackers" WHERE "spree_trackers"."active" = 't' AND "spree_trackers"."environment" = 'development' ORDER BY "spree_trackers"."id" ASC LIMIT 1[0m
  Rendered /usr/local/rvm/gems/ruby-2.0.0-p247@spreescratch/gems/spree_frontend-2.1.1/app/views/spree/shared/_google_analytics.html.erb (2.4ms)
Completed 200 OK in 344ms (Views: 315.0ms | ActiveRecord: 6.8ms)


Started GET "/assets/skeleton.css?body=1" for 127.0.0.1 at 2013-10-06 16:27:31 +1100


Started GET "/assets/normalize.css?body=1" for 127.0.0.1 at 2013-10-06 16:27:31 +1100


Started GET "/assets/store/spree_frontend.css?body=1" for 127.0.0.1 at 2013-10-06 16:27:31 +1100


Started GET "/assets/store/screen.css?body=1" for 127.0.0.1 at 2013-10-06 16:27:31 +1100


Started GET "/assets/store/all.css?body=1" for 127.0.0.1 at 2013-10-06 16:27:31 +1100


Started GET "/assets/spree.js?body=1" for 127.0.0.1 at 2013-10-06 16:27:32 +1100


Started GET "/assets/jquery.payment.js?body=1" for 127.0.0.1 at 2013-10-06 16:27:32 +1100


Started GET "/assets/jquery.js?body=1" for 127.0.0.1 at 2013-10-06 16:27:32 +1100


Started GET "/assets/jquery_ujs.js?body=1" for 127.0.0.1 at 2013-10-06 16:27:32 +1100


Started GET "/assets/jsuri.js?body=1" for 127.0.0.1 at 2013-10-06 16:27:32 +1100


Started GET "/assets/store/checkout.js?body=1" for 127.0.0.1 at 2013-10-06 16:27:32 +1100


Started GET "/assets/jquery.validate/jquery.validate.min.js?body=1" for 127.0.0.1 at 2013-10-06 16:27:32 +1100


Started GET "/assets/store/product.js?body=1" for 127.0.0.1 at 2013-10-06 16:27:32 +1100


Started GET "/assets/store/cart.js?body=1" for 127.0.0.1 at 2013-10-06 16:27:32 +1100


Started GET "/assets/store/spree_frontend.js?body=1" for 127.0.0.1 at 2013-10-06 16:27:32 +1100


Started GET "/assets/store/all.js?body=1" for 127.0.0.1 at 2013-10-06 16:27:32 +1100


Started GET "/assets/logo/spree_50.png" for 127.0.0.1 at 2013-10-06 16:27:32 +1100


Started GET "/assets/store/cart.png" for 127.0.0.1 at 2013-10-06 16:27:32 +1100


Started GET "/assets/credit_cards/icons/visa.png" for 127.0.0.1 at 2013-10-06 16:27:32 +1100


Started PATCH "/checkout/update/confirm" for 127.0.0.1 at 2013-10-06 16:28:25 +1100
Processing by Spree::CheckoutController#update as HTML
  Parameters: {"utf8"=>"✓", "authenticity_token"=>"ULTMChoByuqOylMyc2kVfmDUPIWsHuZk+ytf6hvkgrY=", "state"=>"confirm"}
  [1m[35mSpree::User Load (0.3ms)[0m  SELECT "spree_users".* FROM "spree_users" WHERE "spree_users"."id" = 1 ORDER BY "spree_users"."id" ASC LIMIT 1
  [1m[36mSpree::Preference Load (0.2ms)[0m  [1mSELECT "spree_preferences".* FROM "spree_preferences" WHERE "spree_preferences"."key" = '/spree/frontend_configuration/locale' LIMIT 1[0m
  [1m[35mSpree::Order Load (0.3ms)[0m  SELECT "spree_orders".* FROM "spree_orders" WHERE "spree_orders"."user_id" = ? AND "spree_orders"."completed_at" IS NULL AND "spree_orders"."created_by_id" = 1 ORDER BY created_at DESC LIMIT 1  [["user_id", 1]]
  [1m[36mSpree::Order Load (0.2ms)[0m  [1mSELECT "spree_orders".* FROM "spree_orders" WHERE "spree_orders"."id" = 3 AND "spree_orders"."currency" = 'USD' LIMIT 1[0m
  [1m[35mSpree::Adjustment Load (0.3ms)[0m  SELECT "spree_adjustments".* FROM "spree_adjustments" WHERE "spree_adjustments"."adjustable_type" = 'Spree::Order' AND "spree_adjustments"."adjustable_id" IN (3) ORDER BY spree_adjustments.created_at ASC
  [1m[36mSpree::Payment Load (0.1ms)[0m  [1mSELECT "spree_payments".* FROM "spree_payments" WHERE "spree_payments"."order_id" = ? AND "spree_payments"."state" = 'completed'[0m  [["order_id", 3]]
  [1m[35mSpree::LineItem Load (0.1ms)[0m  SELECT "spree_line_items".* FROM "spree_line_items" WHERE "spree_line_items"."order_id" = ? ORDER BY created_at ASC  [["order_id", 3]]
  [1m[36mSpree::Adjustment Load (0.3ms)[0m  [1mSELECT "spree_adjustments".* FROM "spree_adjustments" WHERE "spree_adjustments"."adjustable_id" = ? AND "spree_adjustments"."adjustable_type" = ? AND "spree_adjustments"."eligible" = 't' ORDER BY spree_adjustments.created_at ASC[0m  [["adjustable_id", 3], ["adjustable_type", "Spree::Order"]]
  [1m[35mSpree::Payment Load (0.1ms)[0m  SELECT "spree_payments".* FROM "spree_payments" WHERE "spree_payments"."order_id" = ?  [["order_id", 3]]
  [1m[36mSpree::PaymentMethod Load (0.1ms)[0m  [1mSELECT "spree_payment_methods".* FROM "spree_payment_methods" WHERE "spree_payment_methods"."deleted_at" IS NULL AND "spree_payment_methods"."id" = ? ORDER BY "spree_payment_methods"."id" ASC LIMIT 1[0m  [["id", 6]]
  [1m[35mCACHE (0.0ms)[0m  SELECT "spree_payments".* FROM "spree_payments" WHERE "spree_payments"."order_id" = ? AND "spree_payments"."state" = 'completed'  [["order_id", 3]]
  [1m[36mCACHE (0.0ms)[0m  [1mSELECT "spree_adjustments".* FROM "spree_adjustments" WHERE "spree_adjustments"."adjustable_id" = ? AND "spree_adjustments"."adjustable_type" = ? AND "spree_adjustments"."eligible" = 't' ORDER BY spree_adjustments.created_at ASC[0m  [["adjustable_id", 3], ["adjustable_type", "Spree::Order"]]
  [1m[35mCACHE (0.0ms)[0m  SELECT "spree_payments".* FROM "spree_payments" WHERE "spree_payments"."order_id" = ? AND "spree_payments"."state" = 'completed'  [["order_id", 3]]
  [1m[36mCACHE (0.0ms)[0m  [1mSELECT "spree_adjustments".* FROM "spree_adjustments" WHERE "spree_adjustments"."adjustable_id" = ? AND "spree_adjustments"."adjustable_type" = ? AND "spree_adjustments"."eligible" = 't' ORDER BY spree_adjustments.created_at ASC[0m  [["adjustable_id", 3], ["adjustable_type", "Spree::Order"]]
  [1m[35mCACHE (0.0ms)[0m  SELECT "spree_payments".* FROM "spree_payments" WHERE "spree_payments"."order_id" = ? AND "spree_payments"."state" = 'completed'  [["order_id", 3]]
  [1m[36mCACHE (0.0ms)[0m  [1mSELECT "spree_adjustments".* FROM "spree_adjustments" WHERE "spree_adjustments"."adjustable_id" = ? AND "spree_adjustments"."adjustable_type" = ? AND "spree_adjustments"."eligible" = 't' ORDER BY spree_adjustments.created_at ASC[0m  [["adjustable_id", 3], ["adjustable_type", "Spree::Order"]]
  [1m[35m (0.1ms)[0m  SELECT COUNT(*) FROM "spree_line_items" WHERE "spree_line_items"."order_id" = ?  [["order_id", 3]]
  [1m[36mSpree::StockItem Load (0.2ms)[0m  [1mSELECT "spree_stock_items".* FROM "spree_stock_items" INNER JOIN "spree_stock_locations" ON "spree_stock_locations"."id" = "spree_stock_items"."stock_location_id" WHERE "spree_stock_items"."deleted_at" IS NULL AND "spree_stock_items"."variant_id" = 7 AND "spree_stock_locations"."active" = 't'[0m
  [1m[35mCACHE (0.0ms)[0m  SELECT "spree_payments".* FROM "spree_payments" WHERE "spree_payments"."order_id" = ? AND "spree_payments"."state" = 'completed'  [["order_id", 3]]
  [1m[36mCACHE (0.0ms)[0m  [1mSELECT "spree_adjustments".* FROM "spree_adjustments" WHERE "spree_adjustments"."adjustable_id" = ? AND "spree_adjustments"."adjustable_type" = ? AND "spree_adjustments"."eligible" = 't' ORDER BY spree_adjustments.created_at ASC[0m  [["adjustable_id", 3], ["adjustable_type", "Spree::Order"]]
  [1m[35mSpree::User Load (0.1ms)[0m  SELECT "spree_users".* FROM "spree_users" WHERE "spree_users"."id" = ? ORDER BY "spree_users"."id" ASC LIMIT 1  [["id", 1]]
  [1m[36m (0.2ms)[0m  [1mSELECT COUNT(*) FROM "spree_roles" INNER JOIN "spree_roles_users" ON "spree_roles"."id" = "spree_roles_users"."role_id" WHERE "spree_roles_users"."user_id" = ? AND "spree_roles"."name" = 'admin'[0m  [["user_id", 1]]
  [1m[35mCACHE (0.0ms)[0m  SELECT "spree_payments".* FROM "spree_payments" WHERE "spree_payments"."order_id" = ? AND "spree_payments"."state" = 'completed'  [["order_id", 3]]
  [1m[36mCACHE (0.0ms)[0m  [1mSELECT "spree_adjustments".* FROM "spree_adjustments" WHERE "spree_adjustments"."adjustable_id" = ? AND "spree_adjustments"."adjustable_type" = ? AND "spree_adjustments"."eligible" = 't' ORDER BY spree_adjustments.created_at ASC[0m  [["adjustable_id", 3], ["adjustable_type", "Spree::Order"]]
  [1m[35m (0.1ms)[0m  begin transaction
  [1m[36mCACHE (0.0ms)[0m  [1mSELECT "spree_payments".* FROM "spree_payments" WHERE "spree_payments"."order_id" = ? AND "spree_payments"."state" = 'completed'[0m  [["order_id", 3]]
  [1m[35mCACHE (0.0ms)[0m  SELECT "spree_adjustments".* FROM "spree_adjustments" WHERE "spree_adjustments"."adjustable_id" = ? AND "spree_adjustments"."adjustable_type" = ? AND "spree_adjustments"."eligible" = 't' ORDER BY spree_adjustments.created_at ASC  [["adjustable_id", 3], ["adjustable_type", "Spree::Order"]]
  [1m[36m (0.1ms)[0m  [1mcommit transaction[0m
  [1m[35m (0.1ms)[0m  begin transaction
  [1m[36mSpree::CreditCard Load (0.1ms)[0m  [1mSELECT "spree_credit_cards".* FROM "spree_credit_cards" WHERE "spree_credit_cards"."id" = ? ORDER BY "spree_credit_cards"."id" ASC LIMIT 1[0m  [["id", 2]]
  [1m[35mSpree::Preference Load (0.2ms)[0m  SELECT "spree_preferences".* FROM "spree_preferences" WHERE "spree_preferences"."key" = '/spree/app_configuration/auto_capture' LIMIT 1
  [1m[36mSpree::Payment Exists (0.2ms)[0m  [1mSELECT 1 AS one FROM "spree_payments" WHERE "spree_payments"."identifier" = 'F89B3A9L' LIMIT 1[0m
  [1m[35mSQL (0.5ms)[0m  UPDATE "spree_payments" SET "state" = ?, "identifier" = ?, "updated_at" = ? WHERE "spree_payments"."id" = 3  [["state", "processing"], ["identifier", "F89B3A9L"], ["updated_at", Sun, 06 Oct 2013 05:28:25 UTC +00:00]]
  [1m[36mSpree::Order Load (0.1ms)[0m  [1mSELECT "spree_orders".* FROM "spree_orders" WHERE "spree_orders"."id" = ? ORDER BY "spree_orders"."id" ASC LIMIT 1[0m  [["id", 3]]
  [1m[35mSpree::Payment Load (0.1ms)[0m  SELECT "spree_payments".* FROM "spree_payments" WHERE "spree_payments"."order_id" = ?  [["order_id", 3]]
  [1m[36mSpree::Payment Load (0.1ms)[0m  [1mSELECT "spree_payments".* FROM "spree_payments" WHERE "spree_payments"."order_id" = ? AND "spree_payments"."state" = 'completed'[0m  [["order_id", 3]]
  [1m[35mSpree::LineItem Load (0.2ms)[0m  SELECT "spree_line_items".* FROM "spree_line_items" WHERE "spree_line_items"."order_id" = ? ORDER BY created_at ASC  [["order_id", 3]]
  [1m[36mSpree::Adjustment Load (0.2ms)[0m  [1mSELECT "spree_adjustments".* FROM "spree_adjustments" WHERE "spree_adjustments"."adjustable_id" = ? AND "spree_adjustments"."adjustable_type" = ? AND "spree_adjustments"."eligible" = 't' ORDER BY spree_adjustments.created_at ASC[0m  [["adjustable_id", 3], ["adjustable_type", "Spree::Order"]]
  [1m[35mSpree::Adjustment Load (0.3ms)[0m  SELECT "spree_adjustments".* FROM "spree_adjustments" WHERE "spree_adjustments"."adjustable_id" = ? AND "spree_adjustments"."adjustable_type" = ? ORDER BY spree_adjustments.created_at ASC  [["adjustable_id", 3], ["adjustable_type", "Spree::Order"]]
  [1m[36mSpree::Adjustment Load (0.2ms)[0m  [1mSELECT "spree_adjustments".* FROM "spree_adjustments" WHERE "spree_adjustments"."adjustable_id" = ? AND "spree_adjustments"."adjustable_type" = ? AND "spree_adjustments"."originator_type" = 'Spree::PromotionAction' ORDER BY spree_adjustments.created_at ASC[0m  [["adjustable_id", 3], ["adjustable_type", "Spree::Order"]]
  [1m[35mSpree::Adjustment Load (0.1ms)[0m  SELECT "spree_adjustments".* FROM "spree_adjustments" WHERE "spree_adjustments"."adjustable_id" = ? AND "spree_adjustments"."adjustable_type" = ? AND "spree_adjustments"."originator_type" = 'Spree::PromotionAction' AND "spree_adjustments"."eligible" = 't' ORDER BY amount ASC, created_at DESC LIMIT 1  [["adjustable_id", 3], ["adjustable_type", "Spree::Order"]]
  [1m[36mCACHE (0.0ms)[0m  [1mSELECT "spree_adjustments".* FROM "spree_adjustments" WHERE "spree_adjustments"."adjustable_id" = ? AND "spree_adjustments"."adjustable_type" = ? ORDER BY spree_adjustments.created_at ASC[0m  [["adjustable_id", 3], ["adjustable_type", "Spree::Order"]]
  [1m[35mSpree::Adjustment Load (0.2ms)[0m  SELECT "spree_adjustments".* FROM "spree_adjustments" WHERE "spree_adjustments"."adjustable_id" = ? AND "spree_adjustments"."adjustable_type" = ? AND "spree_adjustments"."originator_type" = 'Spree::ShippingMethod' ORDER BY spree_adjustments.created_at ASC  [["adjustable_id", 3], ["adjustable_type", "Spree::Order"]]
  [1m[36mSpree::Adjustment Load (0.1ms)[0m  [1mSELECT "spree_adjustments".* FROM "spree_adjustments" WHERE "spree_adjustments"."id" = ? LIMIT 1[0m  [["id", 9]]
  [1m[35mSpree::ShippingMethod Load (0.1ms)[0m  SELECT "spree_shipping_methods".* FROM "spree_shipping_methods" WHERE "spree_shipping_methods"."deleted_at" IS NULL AND "spree_shipping_methods"."id" = ? ORDER BY "spree_shipping_methods"."id" ASC LIMIT 1  [["id", 5]]
  [1m[36mSpree::Shipment Load (0.1ms)[0m  [1mSELECT "spree_shipments".* FROM "spree_shipments" WHERE "spree_shipments"."id" = ? ORDER BY "spree_shipments"."id" ASC LIMIT 1[0m  [["id", 3]]
  [1m[35mSpree::StockLocation Load (0.1ms)[0m  SELECT "spree_stock_locations".* FROM "spree_stock_locations" WHERE "spree_stock_locations"."id" = ? ORDER BY "spree_stock_locations"."id" ASC LIMIT 1  [["id", 1]]
  [1m[36mCACHE (0.0ms)[0m  [1mSELECT "spree_orders".* FROM "spree_orders" WHERE "spree_orders"."id" = ? ORDER BY "spree_orders"."id" ASC LIMIT 1[0m  [["id", 3]]
  [1m[35mSpree::InventoryUnit Load (0.1ms)[0m  SELECT "spree_inventory_units".* FROM "spree_inventory_units" WHERE "spree_inventory_units"."shipment_id" = ?  [["shipment_id", 3]]
  [1m[36mSpree::Variant Load (0.4ms)[0m  [1mSELECT "spree_variants".* FROM "spree_variants" WHERE "spree_variants"."deleted_at" IS NULL AND "spree_variants"."id" IN (7)[0m
  [1m[35mSpree::Calculator Load (0.1ms)[0m  SELECT "spree_calculators".* FROM "spree_calculators" WHERE "spree_calculators"."calculable_id" = ? AND "spree_calculators"."calculable_type" = ? ORDER BY "spree_calculators"."id" ASC LIMIT 1  [["calculable_id", 5], ["calculable_type", "Spree::ShippingMethod"]]
  [1m[36mSpree::Price Load (0.1ms)[0m  [1mSELECT "spree_prices".* FROM "spree_prices" WHERE "spree_prices"."variant_id" = ? AND "spree_prices"."currency" = 'USD' ORDER BY "spree_prices"."id" ASC LIMIT 1[0m  [["variant_id", 7]]
  [1m[35mSQL (0.1ms)[0m  UPDATE "spree_adjustments" SET "amount" = 0.0 WHERE "spree_adjustments"."id" = 9
  [1m[36mSQL (0.1ms)[0m  [1mUPDATE "spree_adjustments" SET "eligible" = 't' WHERE "spree_adjustments"."id" = 9[0m
  [1m[35mSpree::Payment Load (0.1ms)[0m  SELECT "spree_payments".* FROM "spree_payments" WHERE "spree_payments"."order_id" = ? AND "spree_payments"."state" = 'completed'  [["order_id", 3]]
  [1m[36mSpree::Adjustment Load (0.2ms)[0m  [1mSELECT "spree_adjustments".* FROM "spree_adjustments" WHERE "spree_adjustments"."adjustable_id" = ? AND "spree_adjustments"."adjustable_type" = ? AND "spree_adjustments"."eligible" = 't' ORDER BY spree_adjustments.created_at ASC[0m  [["adjustable_id", 3], ["adjustable_type", "Spree::Order"]]
  [1m[35mSQL (0.1ms)[0m  UPDATE "spree_orders" SET "payment_state" = NULL, "shipment_state" = NULL, "item_total" = 19.99, "adjustment_total" = 0.0, "payment_total" = 0.0, "total" = 19.99 WHERE "spree_orders"."id" = 3
  [1m[36mSpree::Adjustment Load (0.2ms)[0m  [1mSELECT "spree_adjustments".* FROM "spree_adjustments" WHERE "spree_adjustments"."adjustable_id" = ? AND "spree_adjustments"."adjustable_type" = ? AND "spree_adjustments"."originator_type" = 'Spree::ShippingMethod' ORDER BY spree_adjustments.created_at ASC[0m  [["adjustable_id", 3], ["adjustable_type", "Spree::Order"]]
  [1m[35mSpree::Adjustment Load (0.2ms)[0m  SELECT "spree_adjustments".* FROM "spree_adjustments" WHERE "spree_adjustments"."adjustable_id" = ? AND "spree_adjustments"."adjustable_type" = ? AND "spree_adjustments"."originator_type" = 'Spree::TaxRate' AND "spree_adjustments"."adjustable_type" = 'Spree::Order' ORDER BY spree_adjustments.created_at ASC  [["adjustable_id", 3], ["adjustable_type", "Spree::Order"]]
  [1m[36mSpree::Adjustment Load (0.2ms)[0m  [1mSELECT "spree_adjustments".* FROM "spree_adjustments" WHERE "spree_adjustments"."adjustable_id" = ? AND "spree_adjustments"."adjustable_type" = ? AND "spree_adjustments"."eligible" = 't' AND "spree_adjustments"."originator_type" = 'Spree::PromotionAction' ORDER BY spree_adjustments.created_at ASC[0m  [["adjustable_id", 3], ["adjustable_type", "Spree::Order"]]
  [1m[35mSpree::Address Load (0.1ms)[0m  SELECT "spree_addresses".* FROM "spree_addresses" WHERE "spree_addresses"."id" = ? ORDER BY "spree_addresses"."id" ASC LIMIT 1  [["id", 3]]
  [1m[36mSpree::Country Load (0.1ms)[0m  [1mSELECT "spree_countries".* FROM "spree_countries" WHERE "spree_countries"."id" = ? ORDER BY "spree_countries"."id" ASC LIMIT 1[0m  [["id", 109]]
  [1m[35mSpree::Address Load (0.1ms)[0m  SELECT "spree_addresses".* FROM "spree_addresses" WHERE "spree_addresses"."id" = ? ORDER BY "spree_addresses"."id" ASC LIMIT 1  [["id", 4]]
  [1m[36mCACHE (0.0ms)[0m  [1mSELECT "spree_countries".* FROM "spree_countries" WHERE "spree_countries"."id" = ? ORDER BY "spree_countries"."id" ASC LIMIT 1[0m  [["id", 109]]
  [1m[35mSQL (12.4ms)[0m  INSERT INTO "spree_log_entries" ("created_at", "details", "source_id", "source_type", "updated_at") VALUES (?, ?, ?, ?, ?)  [["created_at", Sun, 06 Oct 2013 05:28:27 UTC +00:00], ["details", "--- !ruby/object:ActiveMerchant::Billing::Response\nparams:\n  error:\n    message: The card object must have a value for 'number'.\n    type: card_error\n    param: number\n    code: invalid_number\nmessage: The card object must have a value for 'number'.\nsuccess: false\ntest: false\nauthorization: \nfraud_review: \navs_result:\n  code: \n  message: \n  street_match: \n  postal_match: \ncvv_result:\n  code: \n  message: \n"], ["source_id", 3], ["source_type", "Spree::Payment"], ["updated_at", Sun, 06 Oct 2013 05:28:27 UTC +00:00]]
  [1m[36mSpree::Payment Exists (0.1ms)[0m  [1mSELECT 1 AS one FROM "spree_payments" WHERE "spree_payments"."identifier" = 'EN8E27ZZ' LIMIT 1[0m
  [1m[35mSQL (0.4ms)[0m  UPDATE "spree_payments" SET "state" = ?, "identifier" = ?, "updated_at" = ? WHERE "spree_payments"."id" = 3  [["state", "failed"], ["identifier", "EN8E27ZZ"], ["updated_at", Sun, 06 Oct 2013 05:28:27 UTC +00:00]]
  [1m[36mSpree::Payment Load (0.1ms)[0m  [1mSELECT "spree_payments".* FROM "spree_payments" WHERE "spree_payments"."order_id" = ?[0m  [["order_id", 3]]
  [1m[35mSpree::Payment Load (0.1ms)[0m  SELECT "spree_payments".* FROM "spree_payments" WHERE "spree_payments"."order_id" = ? AND "spree_payments"."state" = 'completed'  [["order_id", 3]]
  [1m[36mSpree::Adjustment Load (0.1ms)[0m  [1mSELECT "spree_adjustments".* FROM "spree_adjustments" WHERE "spree_adjustments"."adjustable_id" = ? AND "spree_adjustments"."adjustable_type" = ? AND "spree_adjustments"."eligible" = 't' ORDER BY spree_adjustments.created_at ASC[0m  [["adjustable_id", 3], ["adjustable_type", "Spree::Order"]]
  [1m[35mSpree::Adjustment Load (0.1ms)[0m  SELECT "spree_adjustments".* FROM "spree_adjustments" WHERE "spree_adjustments"."adjustable_id" = ? AND "spree_adjustments"."adjustable_type" = ? ORDER BY spree_adjustments.created_at ASC  [["adjustable_id", 3], ["adjustable_type", "Spree::Order"]]
  [1m[36mSpree::Adjustment Load (0.2ms)[0m  [1mSELECT "spree_adjustments".* FROM "spree_adjustments" WHERE "spree_adjustments"."adjustable_id" = ? AND "spree_adjustments"."adjustable_type" = ? AND "spree_adjustments"."originator_type" = 'Spree::PromotionAction' ORDER BY spree_adjustments.created_at ASC[0m  [["adjustable_id", 3], ["adjustable_type", "Spree::Order"]]
  [1m[35mSpree::Adjustment Load (0.1ms)[0m  SELECT "spree_adjustments".* FROM "spree_adjustments" WHERE "spree_adjustments"."adjustable_id" = ? AND "spree_adjustments"."adjustable_type" = ? AND "spree_adjustments"."originator_type" = 'Spree::PromotionAction' AND "spree_adjustments"."eligible" = 't' ORDER BY amount ASC, created_at DESC LIMIT 1  [["adjustable_id", 3], ["adjustable_type", "Spree::Order"]]
  [1m[36mCACHE (0.0ms)[0m  [1mSELECT "spree_adjustments".* FROM "spree_adjustments" WHERE "spree_adjustments"."adjustable_id" = ? AND "spree_adjustments"."adjustable_type" = ? ORDER BY spree_adjustments.created_at ASC[0m  [["adjustable_id", 3], ["adjustable_type", "Spree::Order"]]
  [1m[35mSpree::Adjustment Load (0.1ms)[0m  SELECT "spree_adjustments".* FROM "spree_adjustments" WHERE "spree_adjustments"."adjustable_id" = ? AND "spree_adjustments"."adjustable_type" = ? AND "spree_adjustments"."originator_type" = 'Spree::ShippingMethod' ORDER BY spree_adjustments.created_at ASC  [["adjustable_id", 3], ["adjustable_type", "Spree::Order"]]
  [1m[36mSpree::Adjustment Load (0.1ms)[0m  [1mSELECT "spree_adjustments".* FROM "spree_adjustments" WHERE "spree_adjustments"."id" = ? LIMIT 1[0m  [["id", 9]]
  [1m[35mSpree::ShippingMethod Load (0.1ms)[0m  SELECT "spree_shipping_methods".* FROM "spree_shipping_methods" WHERE "spree_shipping_methods"."deleted_at" IS NULL AND "spree_shipping_methods"."id" = ? ORDER BY "spree_shipping_methods"."id" ASC LIMIT 1  [["id", 5]]
  [1m[36mSpree::Shipment Load (0.1ms)[0m  [1mSELECT "spree_shipments".* FROM "spree_shipments" WHERE "spree_shipments"."id" = ? ORDER BY "spree_shipments"."id" ASC LIMIT 1[0m  [["id", 3]]
  [1m[35mSpree::StockLocation Load (0.1ms)[0m  SELECT "spree_stock_locations".* FROM "spree_stock_locations" WHERE "spree_stock_locations"."id" = ? ORDER BY "spree_stock_locations"."id" ASC LIMIT 1  [["id", 1]]
  [1m[36mSpree::Order Load (0.1ms)[0m  [1mSELECT "spree_orders".* FROM "spree_orders" WHERE "spree_orders"."id" = ? ORDER BY "spree_orders"."id" ASC LIMIT 1[0m  [["id", 3]]
  [1m[35mSpree::InventoryUnit Load (0.1ms)[0m  SELECT "spree_inventory_units".* FROM "spree_inventory_units" WHERE "spree_inventory_units"."shipment_id" = ?  [["shipment_id", 3]]
  [1m[36mSpree::Variant Load (0.2ms)[0m  [1mSELECT "spree_variants".* FROM "spree_variants" WHERE "spree_variants"."deleted_at" IS NULL AND "spree_variants"."id" IN (7)[0m
  [1m[35mSpree::Calculator Load (0.1ms)[0m  SELECT "spree_calculators".* FROM "spree_calculators" WHERE "spree_calculators"."calculable_id" = ? AND "spree_calculators"."calculable_type" = ? ORDER BY "spree_calculators"."id" ASC LIMIT 1  [["calculable_id", 5], ["calculable_type", "Spree::ShippingMethod"]]
  [1m[36mSpree::Price Load (0.1ms)[0m  [1mSELECT "spree_prices".* FROM "spree_prices" WHERE "spree_prices"."variant_id" = ? AND "spree_prices"."currency" = 'USD' ORDER BY "spree_prices"."id" ASC LIMIT 1[0m  [["variant_id", 7]]
  [1m[35mSQL (0.1ms)[0m  UPDATE "spree_adjustments" SET "amount" = 0.0 WHERE "spree_adjustments"."id" = 9
  [1m[36mSQL (0.1ms)[0m  [1mUPDATE "spree_adjustments" SET "eligible" = 't' WHERE "spree_adjustments"."id" = 9[0m
  [1m[35mSpree::Payment Load (0.1ms)[0m  SELECT "spree_payments".* FROM "spree_payments" WHERE "spree_payments"."order_id" = ? AND "spree_payments"."state" = 'completed'  [["order_id", 3]]
  [1m[36mSpree::Adjustment Load (0.1ms)[0m  [1mSELECT "spree_adjustments".* FROM "spree_adjustments" WHERE "spree_adjustments"."adjustable_id" = ? AND "spree_adjustments"."adjustable_type" = ? AND "spree_adjustments"."eligible" = 't' ORDER BY spree_adjustments.created_at ASC[0m  [["adjustable_id", 3], ["adjustable_type", "Spree::Order"]]
  [1m[35mSQL (0.1ms)[0m  UPDATE "spree_orders" SET "payment_state" = NULL, "shipment_state" = NULL, "item_total" = 19.99, "adjustment_total" = 0.0, "payment_total" = 0.0, "total" = 19.99 WHERE "spree_orders"."id" = 3
Gateway Error
  --- !ruby/object:ActiveMerchant::Billing::Response
params:
  error:
    message: The card object must have a value for 'number'.
    type: card_error
    param: number
    code: invalid_number
message: The card object must have a value for 'number'.
success: false
test: false
authorization:
fraud_review:
avs_result:
  code:
  message:
  street_match:
  postal_match:
cvv_result:
  code:
  message:

  [1m[36mSpree::Preference Load (0.1ms)[0m  [1mSELECT "spree_preferences".* FROM "spree_preferences" WHERE "spree_preferences"."key" = '/spree/app_configuration/allow_checkout_on_gateway_error' LIMIT 1[0m
  [1m[35m (16.9ms)[0m  rollback transaction
  [1m[36m (0.1ms)[0m  [1mbegin transaction[0m
  [1m[35mSpree::Payment Exists (0.2ms)[0m  SELECT 1 AS one FROM "spree_payments" WHERE "spree_payments"."identifier" = 'GEZJ4Z9Q' LIMIT 1
  [1m[36mSQL (0.3ms)[0m  [1mUPDATE "spree_payments" SET "state" = ?, "identifier" = ?, "updated_at" = ? WHERE "spree_payments"."id" = 3[0m  [["state", "failed"], ["identifier", "GEZJ4Z9Q"], ["updated_at", Sun, 06 Oct 2013 05:28:27 UTC +00:00]]
  [1m[35mSpree::Payment Load (0.1ms)[0m  SELECT "spree_payments".* FROM "spree_payments" WHERE "spree_payments"."order_id" = ?  [["order_id", 3]]
  [1m[36mSpree::Payment Load (0.0ms)[0m  [1mSELECT "spree_payments".* FROM "spree_payments" WHERE "spree_payments"."order_id" = ? AND "spree_payments"."state" = 'completed'[0m  [["order_id", 3]]
  [1m[35mSpree::Adjustment Load (0.1ms)[0m  SELECT "spree_adjustments".* FROM "spree_adjustments" WHERE "spree_adjustments"."adjustable_id" = ? AND "spree_adjustments"."adjustable_type" = ? AND "spree_adjustments"."eligible" = 't' ORDER BY spree_adjustments.created_at ASC  [["adjustable_id", 3], ["adjustable_type", "Spree::Order"]]
  [1m[36mSpree::Adjustment Load (0.1ms)[0m  [1mSELECT "spree_adjustments".* FROM "spree_adjustments" WHERE "spree_adjustments"."adjustable_id" = ? AND "spree_adjustments"."adjustable_type" = ? ORDER BY spree_adjustments.created_at ASC[0m  [["adjustable_id", 3], ["adjustable_type", "Spree::Order"]]
  [1m[35mSpree::Adjustment Load (0.1ms)[0m  SELECT "spree_adjustments".* FROM "spree_adjustments" WHERE "spree_adjustments"."adjustable_id" = ? AND "spree_adjustments"."adjustable_type" = ? AND "spree_adjustments"."originator_type" = 'Spree::PromotionAction' ORDER BY spree_adjustments.created_at ASC  [["adjustable_id", 3], ["adjustable_type", "Spree::Order"]]
  [1m[36mSpree::Adjustment Load (0.1ms)[0m  [1mSELECT "spree_adjustments".* FROM "spree_adjustments" WHERE "spree_adjustments"."adjustable_id" = ? AND "spree_adjustments"."adjustable_type" = ? AND "spree_adjustments"."originator_type" = 'Spree::PromotionAction' AND "spree_adjustments"."eligible" = 't' ORDER BY amount ASC, created_at DESC LIMIT 1[0m  [["adjustable_id", 3], ["adjustable_type", "Spree::Order"]]
  [1m[35mCACHE (0.0ms)[0m  SELECT "spree_adjustments".* FROM "spree_adjustments" WHERE "spree_adjustments"."adjustable_id" = ? AND "spree_adjustments"."adjustable_type" = ? ORDER BY spree_adjustments.created_at ASC  [["adjustable_id", 3], ["adjustable_type", "Spree::Order"]]
  [1m[36mSpree::Adjustment Load (0.1ms)[0m  [1mSELECT "spree_adjustments".* FROM "spree_adjustments" WHERE "spree_adjustments"."adjustable_id" = ? AND "spree_adjustments"."adjustable_type" = ? AND "spree_adjustments"."originator_type" = 'Spree::ShippingMethod' ORDER BY spree_adjustments.created_at ASC[0m  [["adjustable_id", 3], ["adjustable_type", "Spree::Order"]]
  [1m[35mSpree::Adjustment Load (0.1ms)[0m  SELECT "spree_adjustments".* FROM "spree_adjustments" WHERE "spree_adjustments"."id" = ? LIMIT 1  [["id", 9]]
  [1m[36mSpree::ShippingMethod Load (0.1ms)[0m  [1mSELECT "spree_shipping_methods".* FROM "spree_shipping_methods" WHERE "spree_shipping_methods"."deleted_at" IS NULL AND "spree_shipping_methods"."id" = ? ORDER BY "spree_shipping_methods"."id" ASC LIMIT 1[0m  [["id", 5]]
  [1m[35mSpree::Shipment Load (0.1ms)[0m  SELECT "spree_shipments".* FROM "spree_shipments" WHERE "spree_shipments"."id" = ? ORDER BY "spree_shipments"."id" ASC LIMIT 1  [["id", 3]]
  [1m[36mSpree::StockLocation Load (0.1ms)[0m  [1mSELECT "spree_stock_locations".* FROM "spree_stock_locations" WHERE "spree_stock_locations"."id" = ? ORDER BY "spree_stock_locations"."id" ASC LIMIT 1[0m  [["id", 1]]
  [1m[35mSpree::Order Load (0.1ms)[0m  SELECT "spree_orders".* FROM "spree_orders" WHERE "spree_orders"."id" = ? ORDER BY "spree_orders"."id" ASC LIMIT 1  [["id", 3]]
  [1m[36mSpree::InventoryUnit Load (0.1ms)[0m  [1mSELECT "spree_inventory_units".* FROM "spree_inventory_units" WHERE "spree_inventory_units"."shipment_id" = ?[0m  [["shipment_id", 3]]
  [1m[35mSpree::Variant Load (0.3ms)[0m  SELECT "spree_variants".* FROM "spree_variants" WHERE "spree_variants"."deleted_at" IS NULL AND "spree_variants"."id" IN (7)
  [1m[36mSpree::Calculator Load (0.1ms)[0m  [1mSELECT "spree_calculators".* FROM "spree_calculators" WHERE "spree_calculators"."calculable_id" = ? AND "spree_calculators"."calculable_type" = ? ORDER BY "spree_calculators"."id" ASC LIMIT 1[0m  [["calculable_id", 5], ["calculable_type", "Spree::ShippingMethod"]]
  [1m[35mSpree::Price Load (0.1ms)[0m  SELECT "spree_prices".* FROM "spree_prices" WHERE "spree_prices"."variant_id" = ? AND "spree_prices"."currency" = 'USD' ORDER BY "spree_prices"."id" ASC LIMIT 1  [["variant_id", 7]]
  [1m[36mSQL (0.1ms)[0m  [1mUPDATE "spree_adjustments" SET "amount" = 0.0 WHERE "spree_adjustments"."id" = 9[0m
  [1m[35mSQL (0.1ms)[0m  UPDATE "spree_adjustments" SET "eligible" = 't' WHERE "spree_adjustments"."id" = 9
  [1m[36mSpree::Payment Load (0.1ms)[0m  [1mSELECT "spree_payments".* FROM "spree_payments" WHERE "spree_payments"."order_id" = ? AND "spree_payments"."state" = 'completed'[0m  [["order_id", 3]]
  [1m[35mSpree::Adjustment Load (0.2ms)[0m  SELECT "spree_adjustments".* FROM "spree_adjustments" WHERE "spree_adjustments"."adjustable_id" = ? AND "spree_adjustments"."adjustable_type" = ? AND "spree_adjustments"."eligible" = 't' ORDER BY spree_adjustments.created_at ASC  [["adjustable_id", 3], ["adjustable_type", "Spree::Order"]]
  [1m[36mSQL (0.2ms)[0m  [1mUPDATE "spree_orders" SET "payment_state" = NULL, "shipment_state" = NULL, "item_total" = 19.99, "adjustment_total" = 0.0, "payment_total" = 0.0, "total" = 19.99 WHERE "spree_orders"."id" = 3[0m
  [1m[35m (3.6ms)[0m  commit transaction
  [1m[36mSpree::Payment Load (0.3ms)[0m  [1mSELECT "spree_payments".* FROM "spree_payments" WHERE "spree_payments"."id" = ? ORDER BY "spree_payments"."id" ASC LIMIT 1[0m  [["id", 3]]
  [1m[35m (0.1ms)[0m  begin transaction
  [1m[36mSQL (0.4ms)[0m  [1mINSERT INTO "spree_log_entries" ("created_at", "details", "source_id", "source_type", "updated_at") VALUES (?, ?, ?, ?, ?)[0m  [["created_at", Sun, 06 Oct 2013 05:28:27 UTC +00:00], ["details", "--- !ruby/object:ActiveMerchant::Billing::Response\nparams:\n  error:\n    message: The card object must have a value for 'number'.\n    type: card_error\n    param: number\n    code: invalid_number\nmessage: The card object must have a value for 'number'.\nsuccess: false\ntest: false\nauthorization: \nfraud_review: \navs_result:\n  code: \n  message: \n  street_match: \n  postal_match: \ncvv_result:\n  code: \n  message: \n"], ["source_id", 3], ["source_type", "Spree::Payment"], ["updated_at", Sun, 06 Oct 2013 05:28:27 UTC +00:00]]
  [1m[35m (3.0ms)[0m  commit transaction
Redirected to http://0.0.0.0:3000/checkout/confirm
Completed 302 Found in 1978ms (ActiveRecord: 50.8ms)


Started GET "/checkout/confirm" for 127.0.0.1 at 2013-10-06 16:28:27 +1100
Processing by Spree::CheckoutController#edit as HTML
  Parameters: {"state"=>"confirm"}
  [1m[36mSpree::User Load (7.1ms)[0m  [1mSELECT "spree_users".* FROM "spree_users" WHERE "spree_users"."id" = 1 ORDER BY "spree_users"."id" ASC LIMIT 1[0m
  [1m[35mSpree::Preference Load (0.3ms)[0m  SELECT "spree_preferences".* FROM "spree_preferences" WHERE "spree_preferences"."key" = '/spree/frontend_configuration/locale' LIMIT 1
  [1m[36mSpree::Order Load (0.3ms)[0m  [1mSELECT "spree_orders".* FROM "spree_orders" WHERE "spree_orders"."user_id" = ? AND "spree_orders"."completed_at" IS NULL AND "spree_orders"."created_by_id" = 1 ORDER BY created_at DESC LIMIT 1[0m  [["user_id", 1]]
  [1m[35mSpree::Order Load (0.4ms)[0m  SELECT "spree_orders".* FROM "spree_orders" WHERE "spree_orders"."id" = 3 AND "spree_orders"."currency" = 'USD' LIMIT 1
  [1m[36mSpree::Adjustment Load (0.4ms)[0m  [1mSELECT "spree_adjustments".* FROM "spree_adjustments" WHERE "spree_adjustments"."adjustable_type" = 'Spree::Order' AND "spree_adjustments"."adjustable_id" IN (3) ORDER BY spree_adjustments.created_at ASC[0m
  [1m[35mSpree::Payment Load (0.2ms)[0m  SELECT "spree_payments".* FROM "spree_payments" WHERE "spree_payments"."order_id" = ? AND "spree_payments"."state" = 'completed'  [["order_id", 3]]
  [1m[36mSpree::LineItem Load (0.2ms)[0m  [1mSELECT "spree_line_items".* FROM "spree_line_items" WHERE "spree_line_items"."order_id" = ? ORDER BY created_at ASC[0m  [["order_id", 3]]
  [1m[35mSpree::Adjustment Load (0.3ms)[0m  SELECT "spree_adjustments".* FROM "spree_adjustments" WHERE "spree_adjustments"."adjustable_id" = ? AND "spree_adjustments"."adjustable_type" = ? AND "spree_adjustments"."eligible" = 't' ORDER BY spree_adjustments.created_at ASC  [["adjustable_id", 3], ["adjustable_type", "Spree::Order"]]
  [1m[36mSpree::Payment Load (0.1ms)[0m  [1mSELECT "spree_payments".* FROM "spree_payments" WHERE "spree_payments"."order_id" = ?[0m  [["order_id", 3]]
  [1m[35mSpree::PaymentMethod Load (0.2ms)[0m  SELECT "spree_payment_methods".* FROM "spree_payment_methods" WHERE "spree_payment_methods"."deleted_at" IS NULL AND "spree_payment_methods"."id" = ? ORDER BY "spree_payment_methods"."id" ASC LIMIT 1  [["id", 6]]
  [1m[36mCACHE (0.0ms)[0m  [1mSELECT "spree_payments".* FROM "spree_payments" WHERE "spree_payments"."order_id" = ? AND "spree_payments"."state" = 'completed'[0m  [["order_id", 3]]
  [1m[35mCACHE (0.0ms)[0m  SELECT "spree_adjustments".* FROM "spree_adjustments" WHERE "spree_adjustments"."adjustable_id" = ? AND "spree_adjustments"."adjustable_type" = ? AND "spree_adjustments"."eligible" = 't' ORDER BY spree_adjustments.created_at ASC  [["adjustable_id", 3], ["adjustable_type", "Spree::Order"]]
  [1m[36mCACHE (0.0ms)[0m  [1mSELECT "spree_payments".* FROM "spree_payments" WHERE "spree_payments"."order_id" = ? AND "spree_payments"."state" = 'completed'[0m  [["order_id", 3]]
  [1m[35mCACHE (0.0ms)[0m  SELECT "spree_adjustments".* FROM "spree_adjustments" WHERE "spree_adjustments"."adjustable_id" = ? AND "spree_adjustments"."adjustable_type" = ? AND "spree_adjustments"."eligible" = 't' ORDER BY spree_adjustments.created_at ASC  [["adjustable_id", 3], ["adjustable_type", "Spree::Order"]]
  [1m[36mCACHE (0.0ms)[0m  [1mSELECT "spree_payments".* FROM "spree_payments" WHERE "spree_payments"."order_id" = ? AND "spree_payments"."state" = 'completed'[0m  [["order_id", 3]]
  [1m[35mCACHE (0.0ms)[0m  SELECT "spree_adjustments".* FROM "spree_adjustments" WHERE "spree_adjustments"."adjustable_id" = ? AND "spree_adjustments"."adjustable_type" = ? AND "spree_adjustments"."eligible" = 't' ORDER BY spree_adjustments.created_at ASC  [["adjustable_id", 3], ["adjustable_type", "Spree::Order"]]
  [1m[36m (0.2ms)[0m  [1mSELECT COUNT(*) FROM "spree_line_items" WHERE "spree_line_items"."order_id" = ?[0m  [["order_id", 3]]
  [1m[35mSpree::StockItem Load (0.3ms)[0m  SELECT "spree_stock_items".* FROM "spree_stock_items" INNER JOIN "spree_stock_locations" ON "spree_stock_locations"."id" = "spree_stock_items"."stock_location_id" WHERE "spree_stock_items"."deleted_at" IS NULL AND "spree_stock_items"."variant_id" = 7 AND "spree_stock_locations"."active" = 't'
  [1m[36mCACHE (0.0ms)[0m  [1mSELECT "spree_payments".* FROM "spree_payments" WHERE "spree_payments"."order_id" = ? AND "spree_payments"."state" = 'completed'[0m  [["order_id", 3]]
  [1m[35mCACHE (0.0ms)[0m  SELECT "spree_adjustments".* FROM "spree_adjustments" WHERE "spree_adjustments"."adjustable_id" = ? AND "spree_adjustments"."adjustable_type" = ? AND "spree_adjustments"."eligible" = 't' ORDER BY spree_adjustments.created_at ASC  [["adjustable_id", 3], ["adjustable_type", "Spree::Order"]]
  [1m[36mSpree::User Load (0.3ms)[0m  [1mSELECT "spree_users".* FROM "spree_users" WHERE "spree_users"."id" = ? ORDER BY "spree_users"."id" ASC LIMIT 1[0m  [["id", 1]]
  [1m[35m (0.2ms)[0m  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" = ? AND "spree_roles"."name" = 'admin'  [["user_id", 1]]
  Rendered /usr/local/rvm/gems/ruby-2.0.0-p247@spreescratch/gems/spree_core-2.1.1/app/views/spree/shared/_error_messages.html.erb (0.3ms)
  [1m[36mCACHE (0.0ms)[0m  [1mSELECT "spree_payments".* FROM "spree_payments" WHERE "spree_payments"."order_id" = ? AND "spree_payments"."state" = 'completed'[0m  [["order_id", 3]]
  [1m[35mCACHE (0.0ms)[0m  SELECT "spree_adjustments".* FROM "spree_adjustments" WHERE "spree_adjustments"."adjustable_id" = ? AND "spree_adjustments"."adjustable_type" = ? AND "spree_adjustments"."eligible" = 't' ORDER BY spree_adjustments.created_at ASC  [["adjustable_id", 3], ["adjustable_type", "Spree::Order"]]
  [1m[36mCACHE (0.0ms)[0m  [1mSELECT "spree_payments".* FROM "spree_payments" WHERE "spree_payments"."order_id" = ? AND "spree_payments"."state" = 'completed'[0m  [["order_id", 3]]
  [1m[35mCACHE (0.0ms)[0m  SELECT "spree_adjustments".* FROM "spree_adjustments" WHERE "spree_adjustments"."adjustable_id" = ? AND "spree_adjustments"."adjustable_type" = ? AND "spree_adjustments"."eligible" = 't' ORDER BY spree_adjustments.created_at ASC  [["adjustable_id", 3], ["adjustable_type", "Spree::Order"]]
  [1m[36mCACHE (0.0ms)[0m  [1mSELECT "spree_payments".* FROM "spree_payments" WHERE "spree_payments"."order_id" = ? AND "spree_payments"."state" = 'completed'[0m  [["order_id", 3]]
  [1m[35mCACHE (0.0ms)[0m  SELECT "spree_adjustments".* FROM "spree_adjustments" WHERE "spree_adjustments"."adjustable_id" = ? AND "spree_adjustments"."adjustable_type" = ? AND "spree_adjustments"."eligible" = 't' ORDER BY spree_adjustments.created_at ASC  [["adjustable_id", 3], ["adjustable_type", "Spree::Order"]]
  [1m[36mSpree::Address Load (0.1ms)[0m  [1mSELECT "spree_addresses".* FROM "spree_addresses" WHERE "spree_addresses"."id" = ? ORDER BY "spree_addresses"."id" ASC LIMIT 1[0m  [["id", 4]]
  [1m[35mSpree::Country Load (0.1ms)[0m  SELECT "spree_countries".* FROM "spree_countries" WHERE "spree_countries"."id" = ? ORDER BY "spree_countries"."id" ASC LIMIT 1  [["id", 109]]
  Rendered /usr/local/rvm/gems/ruby-2.0.0-p247@spreescratch/gems/spree_core-2.1.1/app/views/spree/shared/_address.html.erb (1.8ms)
  [1m[36mSpree::Address Load (0.1ms)[0m  [1mSELECT "spree_addresses".* FROM "spree_addresses" WHERE "spree_addresses"."id" = ? ORDER BY "spree_addresses"."id" ASC LIMIT 1[0m  [["id", 3]]
  [1m[35mCACHE (0.0ms)[0m  SELECT "spree_countries".* FROM "spree_countries" WHERE "spree_countries"."id" = ? ORDER BY "spree_countries"."id" ASC LIMIT 1  [["id", 109]]
  Rendered /usr/local/rvm/gems/ruby-2.0.0-p247@spreescratch/gems/spree_core-2.1.1/app/views/spree/shared/_address.html.erb (1.5ms)
  [1m[36mCACHE (0.0ms)[0m  [1mSELECT "spree_payments".* FROM "spree_payments" WHERE "spree_payments"."order_id" = ? AND "spree_payments"."state" = 'completed'[0m  [["order_id", 3]]
  [1m[35mCACHE (0.0ms)[0m  SELECT "spree_adjustments".* FROM "spree_adjustments" WHERE "spree_adjustments"."adjustable_id" = ? AND "spree_adjustments"."adjustable_type" = ? AND "spree_adjustments"."eligible" = 't' ORDER BY spree_adjustments.created_at ASC  [["adjustable_id", 3], ["adjustable_type", "Spree::Order"]]
  [1m[36mSpree::Shipment Load (0.2ms)[0m  [1mSELECT "spree_shipments".* FROM "spree_shipments" WHERE "spree_shipments"."order_id" = ?[0m  [["order_id", 3]]
  [1m[35mSpree::StockLocation Load (0.1ms)[0m  SELECT "spree_stock_locations".* FROM "spree_stock_locations" WHERE "spree_stock_locations"."id" = ? ORDER BY "spree_stock_locations"."id" ASC LIMIT 1  [["id", 1]]
  [1m[36mSpree::ShippingRate Load (0.2ms)[0m  [1mSELECT "spree_shipping_rates".* FROM "spree_shipping_rates" WHERE "spree_shipping_rates"."shipment_id" = ? AND "spree_shipping_rates"."selected" = 't' ORDER BY "spree_shipping_rates"."id" ASC LIMIT 1[0m  [["shipment_id", 3]]
  [1m[35mSpree::ShippingMethod Load (0.1ms)[0m  SELECT "spree_shipping_methods".* FROM "spree_shipping_methods" WHERE "spree_shipping_methods"."deleted_at" IS NULL AND "spree_shipping_methods"."id" = ? ORDER BY "spree_shipping_methods"."id" ASC LIMIT 1  [["id", 5]]
  [1m[36mSpree::Payment Load (0.2ms)[0m  [1mSELECT "spree_payments".* FROM "spree_payments" WHERE "spree_payments"."order_id" = ? AND (state NOT IN ('failed','invalid'))[0m  [["order_id", 3]]
  [1m[35mSpree::Variant Load (0.1ms)[0m  SELECT "spree_variants".* FROM "spree_variants" WHERE "spree_variants"."id" = ? ORDER BY "spree_variants"."id" ASC LIMIT 1  [["id", 7]]
  [1m[36mSpree::Image Load (0.5ms)[0m  [1mSELECT "spree_assets".* FROM "spree_assets" WHERE "spree_assets"."type" IN ('Spree::Image') AND "spree_assets"."viewable_id" = ? AND "spree_assets"."viewable_type" = ? ORDER BY "spree_assets".position ASC[0m  [["viewable_id", 7], ["viewable_type", "Spree::Variant"]]
  [1m[35mSpree::Product Load (0.2ms)[0m  SELECT "spree_products".* FROM "spree_products" WHERE "spree_products"."id" = ? ORDER BY "spree_products"."id" ASC LIMIT 1  [["id", 7]]
  [1m[36mSpree::OptionValue Exists (0.1ms)[0m  [1mSELECT 1 AS one FROM "spree_option_values" INNER JOIN "spree_option_values_variants" ON "spree_option_values"."id" = "spree_option_values_variants"."option_value_id" WHERE "spree_option_values_variants"."variant_id" = ? LIMIT 1[0m  [["variant_id", 7]]
  [1m[35mSpree::Adjustment Load (0.2ms)[0m  SELECT "spree_adjustments".* FROM "spree_adjustments" INNER JOIN "spree_line_items" ON "spree_adjustments"."adjustable_id" = "spree_line_items"."id" AND "spree_adjustments"."adjustable_type" = 'Spree::LineItem' WHERE "spree_line_items"."order_id" = ? AND "spree_adjustments"."eligible" = 't' ORDER BY created_at ASC  [["order_id", 3]]
  [1m[36mCACHE (0.0ms)[0m  [1mSELECT "spree_adjustments".* FROM "spree_adjustments" WHERE "spree_adjustments"."adjustable_id" = ? AND "spree_adjustments"."adjustable_type" = ? AND "spree_adjustments"."eligible" = 't' ORDER BY spree_adjustments.created_at ASC[0m  [["adjustable_id", 3], ["adjustable_type", "Spree::Order"]]
  [1m[35mSpree::Order Load (0.1ms)[0m  SELECT "spree_orders".* FROM "spree_orders" WHERE "spree_orders"."id" = ? ORDER BY "spree_orders"."id" ASC LIMIT 1  [["id", 3]]
  Rendered /usr/local/rvm/gems/ruby-2.0.0-p247@spreescratch/gems/spree_frontend-2.1.1/app/views/spree/shared/_order_details.html.erb (55.4ms)
  Rendered /usr/local/rvm/gems/ruby-2.0.0-p247@spreescratch/gems/spree_frontend-2.1.1/app/views/spree/checkout/_confirm.html.erb (159.0ms)
  Rendered /usr/local/rvm/gems/ruby-2.0.0-p247@spreescratch/gems/spree_frontend-2.1.1/app/views/spree/checkout/edit.html.erb within spree/layouts/spree_application (173.9ms)
  Rendered /usr/local/rvm/gems/ruby-2.0.0-p247@spreescratch/gems/spree_core-2.1.1/app/views/spree/shared/_routes.html.erb (0.5ms)
  Rendered /usr/local/rvm/gems/ruby-2.0.0-p247@spreescratch/gems/spree_frontend-2.1.1/app/views/spree/shared/_head.html.erb (87.9ms)
[1;32mDeface:[0m 1 overrides found for 'spree/shared/_nav_bar'
[1;32mDeface:[0m 'auth_shared_login_bar' matched 1 times with 'li#search-bar'
[1;32mDeface: [ERROR][0m The original source for 'auth_shared_login_bar' has changed, this override should be reviewed to ensure it's still valid.
  [1m[36mSpree::Taxon Load (0.6ms)[0m  [1mSELECT "spree_taxons".* FROM "spree_taxons" WHERE "spree_taxons"."parent_id" IS NULL ORDER BY "lft"[0m
  Rendered /usr/local/rvm/gems/ruby-2.0.0-p247@spreescratch/gems/spree_frontend-2.1.1/app/views/spree/shared/_search.html.erb (3.9ms)
  Rendered /usr/local/rvm/gems/ruby-2.0.0-p247@spreescratch/gems/spree_frontend-2.1.1/app/views/spree/shared/_nav_bar.html.erb (10.6ms)
  Rendered /usr/local/rvm/gems/ruby-2.0.0-p247@spreescratch/gems/spree_frontend-2.1.1/app/views/spree/shared/_main_nav_bar.html.erb (2.5ms)
  Rendered /usr/local/rvm/gems/ruby-2.0.0-p247@spreescratch/gems/spree_frontend-2.1.1/app/views/spree/shared/_header.html.erb (54.6ms)
  Rendered /usr/local/rvm/gems/ruby-2.0.0-p247@spreescratch/gems/spree_frontend-2.1.1/app/views/spree/shared/_footer.html.erb (0.4ms)
  [1m[35mSpree::Tracker Load (0.2ms)[0m  SELECT "spree_trackers".* FROM "spree_trackers" WHERE "spree_trackers"."active" = 't' AND "spree_trackers"."environment" = 'development' ORDER BY "spree_trackers"."id" ASC LIMIT 1
  Rendered /usr/local/rvm/gems/ruby-2.0.0-p247@spreescratch/gems/spree_frontend-2.1.1/app/views/spree/shared/_google_analytics.html.erb (1.2ms)
Completed 200 OK in 384ms (Views: 338.4ms | ActiveRecord: 13.9ms)


Started GET "/assets/normalize.css?body=1" for 127.0.0.1 at 2013-10-06 16:28:28 +1100


Started GET "/assets/skeleton.css?body=1" for 127.0.0.1 at 2013-10-06 16:28:28 +1100


Started GET "/assets/store/spree_frontend.css?body=1" for 127.0.0.1 at 2013-10-06 16:28:28 +1100


Started GET "/assets/store/screen.css?body=1" for 127.0.0.1 at 2013-10-06 16:28:28 +1100


Started GET "/assets/jquery_ujs.js?body=1" for 127.0.0.1 at 2013-10-06 16:28:28 +1100


Started GET "/assets/store/all.css?body=1" for 127.0.0.1 at 2013-10-06 16:28:28 +1100


Started GET "/assets/jquery.validate/jquery.validate.min.js?body=1" for 127.0.0.1 at 2013-10-06 16:28:28 +1100


Started GET "/assets/jquery.js?body=1" for 127.0.0.1 at 2013-10-06 16:28:28 +1100


Started GET "/assets/jsuri.js?body=1" for 127.0.0.1 at 2013-10-06 16:28:28 +1100


Started GET "/assets/spree.js?body=1" for 127.0.0.1 at 2013-10-06 16:28:28 +1100


Started GET "/assets/store/checkout.js?body=1" for 127.0.0.1 at 2013-10-06 16:28:28 +1100


Started GET "/assets/jquery.payment.js?body=1" for 127.0.0.1 at 2013-10-06 16:28:28 +1100


Started GET "/assets/store/product.js?body=1" for 127.0.0.1 at 2013-10-06 16:28:28 +1100


Started GET "/assets/store/cart.js?body=1" for 127.0.0.1 at 2013-10-06 16:28:28 +1100


Started GET "/assets/store/spree_frontend.js?body=1" for 127.0.0.1 at 2013-10-06 16:28:28 +1100


Started GET "/assets/store/all.js?body=1" for 127.0.0.1 at 2013-10-06 16:28:28 +1100


Started GET "/assets/logo/spree_50.png" for 127.0.0.1 at 2013-10-06 16:28:28 +1100


Started GET "/assets/store/cart.png" for 127.0.0.1 at 2013-10-06 16:28:28 +1100