rails (3.1.1)
spree (0.70.1)
spree_paypal_express (bea1aa48e0089083546bec4b19565a40e9a50a20)
Started GET "/orders/R236516735/checkout/paypal_confirm?payment_method_id=931422125&token=EC-3GT761861S960815V&PayerID=8ZF5Q5H5H7TSG" for 127.0.0.1 at Fri Oct 21 13:34:50 +0200 2011
Processing by CheckoutController#paypal_confirm as HTML
Parameters: {"token"=>"EC-3GT761861S960815V", "order_id"=>"R236516735", "payment_method_id"=>"931422125", "PayerID"=>"8ZF5Q5H5H7TSG"}
Preference Load (2.2ms) SELECT `preferences`.* FROM `preferences` WHERE `preferences`.`owner_id` = 1 AND `preferences`.`owner_type` = 'Configuration'
Configuration Load (0.4ms) SELECT `configurations`.* FROM `configurations` WHERE `configurations`.`id` = 1 LIMIT 1
CACHE (0.0ms) SELECT `configurations`.* FROM `configurations` WHERE `configurations`.`id` = 1 LIMIT 1
CACHE (0.0ms) SELECT `configurations`.* FROM `configurations` WHERE `configurations`.`id` = 1 LIMIT 1
CACHE (0.0ms) SELECT `configurations`.* FROM `configurations` WHERE `configurations`.`id` = 1 LIMIT 1
CACHE (0.0ms) SELECT `configurations`.* FROM `configurations` WHERE `configurations`.`id` = 1 LIMIT 1
Order Load (0.5ms) SELECT `orders`.* FROM `orders` WHERE `orders`.`id` = 1069267046 LIMIT 1
Adjustment Load (0.5ms) SELECT `adjustments`.* FROM `adjustments` WHERE `adjustments`.`order_id` IN (1069267046)
(0.4ms) SELECT COUNT(*) FROM `line_items` WHERE `line_items`.`order_id` = 1069267046
LineItem Load (0.5ms) SELECT `line_items`.* FROM `line_items` WHERE `line_items`.`order_id` = 1069267046
User Load (0.5ms) SELECT `users`.* FROM `users` WHERE `users`.`id` = 1 LIMIT 1
Role Load (0.9ms) SELECT `roles`.* FROM `roles` INNER JOIN `roles_users` ON `roles`.`id` = `roles_users`.`role_id` WHERE `roles_users`.`user_id` = 1
SpreeAuthConfiguration Load (0.5ms) SELECT `configurations`.* FROM `configurations` WHERE `configurations`.`type` IN ('SpreeAuthConfiguration') AND `configurations`.`name` = 'Default spree_auth configuration' LIMIT 1
CACHE (0.0ms) SELECT COUNT(*) FROM `line_items` WHERE `line_items`.`order_id` = 1069267046
Variant Load (0.4ms) SELECT `variants`.* FROM `variants` WHERE `variants`.`id` = 215054540 LIMIT 1
Product Load (0.5ms) SELECT `products`.* FROM `products` WHERE `products`.`id` = 459084718 LIMIT 1
Variant Load (0.4ms) SELECT `variants`.* FROM `variants` WHERE `variants`.`id` = 52862384 LIMIT 1
Product Load (0.3ms) SELECT `products`.* FROM `products` WHERE `products`.`id` = 248786582 LIMIT 1
PaymentMethod Load (2.0ms) SELECT `payment_methods`.* FROM `payment_methods` WHERE `payment_methods`.`deleted_at` IS NULL AND `payment_methods`.`id` = 931422125 LIMIT 1
Preference Load (0.6ms) SELECT `preferences`.* FROM `preferences` WHERE `preferences`.`owner_id` = 931422125 AND `preferences`.`owner_type` = 'PaymentMethod' AND `preferences`.`group_id` IS NULL AND `preferences`.`group_type` IS NULL AND `preferences`.`name` = 'currency' LIMIT 1
PaymentMethod Load (0.5ms) SELECT `payment_methods`.* FROM `payment_methods` WHERE `payment_methods`.`deleted_at` IS NULL AND `payment_methods`.`id` = 931422125 LIMIT 1
CACHE (0.0ms) SELECT `payment_methods`.* FROM `payment_methods` WHERE `payment_methods`.`deleted_at` IS NULL AND `payment_methods`.`id` = LIMIT 1
Preference Load (0.8ms) SELECT `preferences`.* FROM `preferences` WHERE `preferences`.`owner_id` = 931422125 AND `preferences`.`owner_type` = 'PaymentMethod'
CACHE (0.0ms) SELECT `payment_methods`.* FROM `payment_methods` WHERE `payment_methods`.`deleted_at` IS NULL AND `payment_methods`.`id` = 931422125 LIMIT 1
CACHE (0.0ms) SELECT `payment_methods`.* FROM `payment_methods` WHERE `payment_methods`.`deleted_at` IS NULL AND `payment_methods`.`id` = 931422125 LIMIT 1
CACHE (0.0ms) SELECT `payment_methods`.* FROM `payment_methods` WHERE `payment_methods`.`deleted_at` IS NULL AND `payment_methods`.`id` = 931422125 LIMIT 1
CACHE (0.0ms) SELECT `payment_methods`.* FROM `payment_methods` WHERE `payment_methods`.`deleted_at` IS NULL AND `payment_methods`.`id` = 931422125 LIMIT 1
CACHE (0.0ms) SELECT `payment_methods`.* FROM `payment_methods` WHERE `payment_methods`.`deleted_at` IS NULL AND `payment_methods`.`id` = 931422125 LIMIT 1
CACHE (0.0ms) SELECT `payment_methods`.* FROM `payment_methods` WHERE `payment_methods`.`deleted_at` IS NULL AND `payment_methods`.`id` = 931422125 LIMIT 1
CACHE (0.0ms) SELECT `payment_methods`.* FROM `payment_methods` WHERE `payment_methods`.`deleted_at` IS NULL AND `payment_methods`.`id` = 931422125 LIMIT 1
CACHE (0.0ms) SELECT `payment_methods`.* FROM `payment_methods` WHERE `payment_methods`.`deleted_at` IS NULL AND `payment_methods`.`id` = 931422125 LIMIT 1
CACHE (0.0ms) SELECT `preferences`.* FROM `preferences` WHERE `preferences`.`owner_id` = 931422125 AND `preferences`.`owner_type` = 'PaymentMethod'
CACHE (0.0ms) SELECT `payment_methods`.* FROM `payment_methods` WHERE `payment_methods`.`deleted_at` IS NULL AND `payment_methods`.`id` = 931422125 LIMIT 1
CACHE (0.0ms) SELECT `payment_methods`.* FROM `payment_methods` WHERE `payment_methods`.`deleted_at` IS NULL AND `payment_methods`.`id` = 931422125 LIMIT 1
CACHE (0.0ms) SELECT `payment_methods`.* FROM `payment_methods` WHERE `payment_methods`.`deleted_at` IS NULL AND `payment_methods`.`id` = 931422125 LIMIT 1
CACHE (0.0ms) SELECT `payment_methods`.* FROM `payment_methods` WHERE `payment_methods`.`deleted_at` IS NULL AND `payment_methods`.`id` = 931422125 LIMIT 1
CACHE (0.0ms) SELECT `payment_methods`.* FROM `payment_methods` WHERE `payment_methods`.`deleted_at` IS NULL AND `payment_methods`.`id` = 931422125 LIMIT 1
CACHE (0.0ms) SELECT `payment_methods`.* FROM `payment_methods` WHERE `payment_methods`.`deleted_at` IS NULL AND `payment_methods`.`id` = 931422125 LIMIT 1
CACHE (0.0ms) SELECT `payment_methods`.* FROM `payment_methods` WHERE `payment_methods`.`deleted_at` IS NULL AND `payment_methods`.`id` = 931422125 LIMIT 1
CACHE (0.0ms) SELECT `payment_methods`.* FROM `payment_methods` WHERE `payment_methods`.`deleted_at` IS NULL AND `payment_methods`.`id` = 931422125 LIMIT 1
(0.2ms) BEGIN
SQL (0.3ms) INSERT INTO `paypal_accounts` (`email`, `payer_country`, `payer_id`, `payer_status`) VALUES ('[email protected]', 'DE', '8ZF5Q5H5H7TSG', 'verified')
(0.6ms) COMMIT
PaymentMethod Load (0.4ms) SELECT `payment_methods`.* FROM `payment_methods` WHERE `payment_methods`.`deleted_at` IS NULL AND `payment_methods`.`id` = 931422125 LIMIT 1
Preference Load (0.4ms) SELECT `preferences`.* FROM `preferences` WHERE `preferences`.`owner_id` = 931422125 AND `preferences`.`owner_type` = 'PaymentMethod' AND `preferences`.`group_id` IS NULL AND `preferences`.`group_type` IS NULL AND `preferences`.`name` = 'no_shipping' LIMIT 1
PaymentMethod Load (0.3ms) SELECT `payment_methods`.* FROM `payment_methods` WHERE `payment_methods`.`deleted_at` IS NULL AND `payment_methods`.`id` = 931422125 LIMIT 1
Country Load (0.5ms) SELECT `countries`.* FROM `countries` WHERE `countries`.`iso` = 'DE' LIMIT 1
State Load (0.4ms) SELECT `states`.* FROM `states` WHERE `states`.`abbr` = 'N/A' LIMIT 1
(0.1ms) BEGIN
SQL (0.5ms) INSERT INTO `addresses` (`address1`, `address2`, `alternative_phone`, `city`, `country_id`, `created_at`, `firstname`, `lastname`, `phone`, `state_id`, `state_name`, `updated_at`, `zipcode`) VALUES ('Obere Hauptstr. 50', NULL, NULL, 'Worms', 74, '2011-10-21 11:34:56', 'Test', 'User', '(not given)', NULL, 'N/A', '2011-10-21 11:34:56', '67551')
(0.6ms) COMMIT
Address Load (0.5ms) SELECT `addresses`.* FROM `addresses` WHERE `addresses`.`id` = 1072978426 LIMIT 1
(0.1ms) BEGIN
Country Load (0.4ms) SELECT `countries`.* FROM `countries` WHERE `countries`.`id` = 74 LIMIT 1
(0.4ms) SELECT 1 FROM `orders` WHERE (`orders`.`number` = BINARY 'R236516735' AND `orders`.`id` != 1069267046) LIMIT 1
(0.4ms) UPDATE `orders` SET `updated_at` = '2011-10-21 11:34:56', `ship_address_id` = 1072978428 WHERE `orders`.`id` = 1069267046
(0.8ms) COMMIT
PaymentMethod Load (0.4ms) SELECT `payment_methods`.* FROM `payment_methods` WHERE `payment_methods`.`deleted_at` IS NULL AND `payment_methods`.`id` = 931422125 LIMIT 1
Preference Load (0.5ms) SELECT `preferences`.* FROM `preferences` WHERE `preferences`.`owner_id` = 931422125 AND `preferences`.`owner_type` = 'PaymentMethod' AND `preferences`.`group_id` IS NULL AND `preferences`.`group_type` IS NULL AND `preferences`.`name` = 'review' LIMIT 1
PaymentMethod Load (0.4ms) SELECT `payment_methods`.* FROM `payment_methods` WHERE `payment_methods`.`deleted_at` IS NULL AND `payment_methods`.`id` = 931422125 LIMIT 1
(0.3ms) SELECT COUNT(*) FROM `line_items` WHERE `line_items`.`order_id` = 1069267046
CACHE (0.0ms) SELECT `payment_methods`.* FROM `payment_methods` WHERE `payment_methods`.`deleted_at` IS NULL AND `payment_methods`.`id` = LIMIT 1
Preference Load (0.5ms) SELECT `preferences`.* FROM `preferences` WHERE `preferences`.`owner_id` = 931422125 AND `preferences`.`owner_type` = 'PaymentMethod' AND `preferences`.`group_id` IS NULL AND `preferences`.`group_type` IS NULL AND `preferences`.`name` = 'currency' LIMIT 1
CACHE (0.0ms) SELECT `payment_methods`.* FROM `payment_methods` WHERE `payment_methods`.`deleted_at` IS NULL AND `payment_methods`.`id` = 931422125 LIMIT 1
CACHE (0.0ms) SELECT `payment_methods`.* FROM `payment_methods` WHERE `payment_methods`.`deleted_at` IS NULL AND `payment_methods`.`id` = LIMIT 1
Preference Load (1.0ms) SELECT `preferences`.* FROM `preferences` WHERE `preferences`.`owner_id` = 931422125 AND `preferences`.`owner_type` = 'PaymentMethod'
CACHE (0.0ms) SELECT `payment_methods`.* FROM `payment_methods` WHERE `payment_methods`.`deleted_at` IS NULL AND `payment_methods`.`id` = 931422125 LIMIT 1
CACHE (0.0ms) SELECT `payment_methods`.* FROM `payment_methods` WHERE `payment_methods`.`deleted_at` IS NULL AND `payment_methods`.`id` = 931422125 LIMIT 1
CACHE (0.0ms) SELECT `payment_methods`.* FROM `payment_methods` WHERE `payment_methods`.`deleted_at` IS NULL AND `payment_methods`.`id` = 931422125 LIMIT 1
CACHE (0.0ms) SELECT `payment_methods`.* FROM `payment_methods` WHERE `payment_methods`.`deleted_at` IS NULL AND `payment_methods`.`id` = 931422125 LIMIT 1
CACHE (0.0ms) SELECT `payment_methods`.* FROM `payment_methods` WHERE `payment_methods`.`deleted_at` IS NULL AND `payment_methods`.`id` = 931422125 LIMIT 1
CACHE (0.0ms) SELECT `payment_methods`.* FROM `payment_methods` WHERE `payment_methods`.`deleted_at` IS NULL AND `payment_methods`.`id` = 931422125 LIMIT 1
CACHE (0.0ms) SELECT `payment_methods`.* FROM `payment_methods` WHERE `payment_methods`.`deleted_at` IS NULL AND `payment_methods`.`id` = 931422125 LIMIT 1
CACHE (0.0ms) SELECT `payment_methods`.* FROM `payment_methods` WHERE `payment_methods`.`deleted_at` IS NULL AND `payment_methods`.`id` = 931422125 LIMIT 1
CACHE (0.0ms) SELECT `preferences`.* FROM `preferences` WHERE `preferences`.`owner_id` = 931422125 AND `preferences`.`owner_type` = 'PaymentMethod'
CACHE (0.0ms) SELECT `payment_methods`.* FROM `payment_methods` WHERE `payment_methods`.`deleted_at` IS NULL AND `payment_methods`.`id` = 931422125 LIMIT 1
CACHE (0.0ms) SELECT `payment_methods`.* FROM `payment_methods` WHERE `payment_methods`.`deleted_at` IS NULL AND `payment_methods`.`id` = 931422125 LIMIT 1
CACHE (0.0ms) SELECT `payment_methods`.* FROM `payment_methods` WHERE `payment_methods`.`deleted_at` IS NULL AND `payment_methods`.`id` = 931422125 LIMIT 1
CACHE (0.0ms) SELECT `payment_methods`.* FROM `payment_methods` WHERE `payment_methods`.`deleted_at` IS NULL AND `payment_methods`.`id` = 931422125 LIMIT 1
CACHE (0.0ms) SELECT `payment_methods`.* FROM `payment_methods` WHERE `payment_methods`.`deleted_at` IS NULL AND `payment_methods`.`id` = 931422125 LIMIT 1
CACHE (0.0ms) SELECT `payment_methods`.* FROM `payment_methods` WHERE `payment_methods`.`deleted_at` IS NULL AND `payment_methods`.`id` = 931422125 LIMIT 1
CACHE (0.0ms) SELECT `payment_methods`.* FROM `payment_methods` WHERE `payment_methods`.`deleted_at` IS NULL AND `payment_methods`.`id` = 931422125 LIMIT 1
CACHE (0.0ms) SELECT `payment_methods`.* FROM `payment_methods` WHERE `payment_methods`.`deleted_at` IS NULL AND `payment_methods`.`id` = 931422125 LIMIT 1
PaypalAccount Load (0.5ms) SELECT `paypal_accounts`.* FROM `paypal_accounts` WHERE `paypal_accounts`.`payer_id` = '8ZF5Q5H5H7TSG' LIMIT 1
(0.2ms) BEGIN
SQL (0.5ms) INSERT INTO `payments` (`amount`, `avs_response`, `created_at`, `order_id`, `payment_method_id`, `response_code`, `source_id`, `source_type`, `state`, `updated_at`) VALUES (0.0, NULL, '2011-10-21 11:35:01', 1069267046, 931422125, 'Failure', 1, 'PaypalAccount', 'checkout', '2011-10-21 11:35:01')
PaymentMethod Load (0.5ms) SELECT `payment_methods`.* FROM `payment_methods` WHERE `payment_methods`.`deleted_at` IS NULL AND `payment_methods`.`id` = 931422125 LIMIT 1
Order Load (0.6ms) SELECT `orders`.* FROM `orders` WHERE `orders`.`id` = 1069267046 LIMIT 1
Payment Load (0.6ms) SELECT `payments`.* FROM `payments` WHERE `payments`.`order_id` = 1069267046
Payment Load (0.5ms) SELECT `payments`.* FROM `payments` WHERE `payments`.`order_id` = 1069267046 AND `payments`.`state` = 'completed'
LineItem Load (0.5ms) SELECT `line_items`.* FROM `line_items` WHERE `line_items`.`order_id` = 1069267046
Adjustment Load (0.6ms) SELECT `adjustments`.* FROM `adjustments` WHERE `adjustments`.`order_id` = 1069267046 AND `adjustments`.`eligible` = 1
Shipment Load (0.8ms) SELECT `shipments`.* FROM `shipments` WHERE `shipments`.`order_id` = 1069267046
InventoryUnit Load (0.5ms) SELECT `inventory_units`.* FROM `inventory_units` WHERE `inventory_units`.`shipment_id` = 1053930507
SQL (0.6ms) UPDATE `shipments` SET `state` = 'pending' WHERE `shipments`.`id` = 1053930507
(0.7ms) SELECT COUNT(*) FROM `shipments` WHERE `shipments`.`order_id` = 1069267046
(0.6ms) SELECT COUNT(*) FROM `shipments` WHERE `shipments`.`order_id` = 1069267046 AND `shipments`.`state` = 'shipped'
(1.5ms) SELECT COUNT(*) FROM `shipments` WHERE `shipments`.`order_id` = 1069267046 AND `shipments`.`state` = 'ready'
(0.5ms) SELECT COUNT(*) FROM `shipments` WHERE `shipments`.`order_id` = 1069267046 AND `shipments`.`state` = 'pending'
(0.6ms) SELECT COUNT(*) FROM `inventory_units` WHERE `inventory_units`.`order_id` = 1069267046 AND `inventory_units`.`state` = 'backordered'
Adjustment Load (0.5ms) SELECT `adjustments`.* FROM `adjustments` WHERE `adjustments`.`order_id` = 1069267046
SQL (0.3ms) UPDATE `adjustments` SET `eligible` = 1 WHERE `adjustments`.`id` = 1073043801
ShippingMethod Load (0.4ms) SELECT `shipping_methods`.* FROM `shipping_methods` WHERE `shipping_methods`.`id` = 574015645 LIMIT 1
Shipment Load (1.0ms) SELECT `shipments`.* FROM `shipments` WHERE `shipments`.`id` = 1053930507 LIMIT 1
Calculator Load (0.5ms) SELECT `calculators`.* FROM `calculators` WHERE `calculators`.`calculable_id` = 574015645 AND `calculators`.`calculable_type` = 'ShippingMethod' LIMIT 1
Preference Load (0.6ms) SELECT `preferences`.* FROM `preferences` WHERE `preferences`.`owner_id` = 574015645 AND `preferences`.`owner_type` = 'Calculator' AND `preferences`.`group_id` IS NULL AND `preferences`.`group_type` IS NULL AND `preferences`.`name` = 'amount' LIMIT 1
Calculator Load (0.5ms) SELECT `calculators`.* FROM `calculators` WHERE `calculators`.`id` = 574015645 LIMIT 1
SQL (0.5ms) UPDATE `adjustments` SET `amount` = 3.9 WHERE `adjustments`.`id` = 1073043801
Adjustment Load (0.5ms) SELECT `adjustments`.* FROM `adjustments` WHERE `adjustments`.`order_id` = 1069267046 AND `adjustments`.`eligible` = 1 AND (label LIKE 'Promotion%')
Payment Load (0.6ms) SELECT `payments`.* FROM `payments` WHERE `payments`.`order_id` = 1069267046 AND `payments`.`state` = 'completed'
Adjustment Load (0.5ms) SELECT `adjustments`.* FROM `adjustments` WHERE `adjustments`.`order_id` = 1069267046 AND `adjustments`.`eligible` = 1
SQL (0.4ms) UPDATE `orders` SET `shipment_state` = 'pending', `adjustment_total` = 3.9, `item_total` = 29.98, `payment_total` = 0.0, `total` = 33.88, `payment_state` = 'balance_due' WHERE `orders`.`id` = 1069267046
SQL (0.4ms) UPDATE `payments` SET `amount` = 33.88 WHERE `payments`.`id` = 121
(0.7ms) COMMIT
(0.1ms) BEGIN
(0.4ms) UPDATE `payments` SET `updated_at` = '2011-10-21 11:35:02', `state` = 'processing' WHERE `payments`.`id` = 121
Payment Load (0.6ms) SELECT `payments`.* FROM `payments` WHERE `payments`.`order_id` = 1069267046
Payment Load (0.5ms) SELECT `payments`.* FROM `payments` WHERE `payments`.`order_id` = 1069267046 AND `payments`.`state` = 'completed'
Adjustment Load (0.5ms) SELECT `adjustments`.* FROM `adjustments` WHERE `adjustments`.`order_id` = 1069267046 AND `adjustments`.`eligible` = 1
SQL (0.3ms) UPDATE `shipments` SET `state` = 'pending' WHERE `shipments`.`id` = 1053930507
(0.4ms) SELECT COUNT(*) FROM `shipments` WHERE `shipments`.`order_id` = 1069267046
(0.7ms) SELECT COUNT(*) FROM `shipments` WHERE `shipments`.`order_id` = 1069267046 AND `shipments`.`state` = 'shipped'
(1.0ms) SELECT COUNT(*) FROM `shipments` WHERE `shipments`.`order_id` = 1069267046 AND `shipments`.`state` = 'ready'
(0.5ms) SELECT COUNT(*) FROM `shipments` WHERE `shipments`.`order_id` = 1069267046 AND `shipments`.`state` = 'pending'
(0.5ms) SELECT COUNT(*) FROM `inventory_units` WHERE `inventory_units`.`order_id` = 1069267046 AND `inventory_units`.`state` = 'backordered'
Adjustment Load (0.4ms) SELECT `adjustments`.* FROM `adjustments` WHERE `adjustments`.`order_id` = 1069267046
SQL (0.3ms) UPDATE `adjustments` SET `eligible` = 1 WHERE `adjustments`.`id` = 1073043801
ShippingMethod Load (0.4ms) SELECT `shipping_methods`.* FROM `shipping_methods` WHERE `shipping_methods`.`id` = 574015645 LIMIT 1
Shipment Load (0.3ms) SELECT `shipments`.* FROM `shipments` WHERE `shipments`.`id` = 1053930507 LIMIT 1
Calculator Load (0.4ms) SELECT `calculators`.* FROM `calculators` WHERE `calculators`.`calculable_id` = 574015645 AND `calculators`.`calculable_type` = 'ShippingMethod' LIMIT 1
Preference Load (0.9ms) SELECT `preferences`.* FROM `preferences` WHERE `preferences`.`owner_id` = 574015645 AND `preferences`.`owner_type` = 'Calculator' AND `preferences`.`group_id` IS NULL AND `preferences`.`group_type` IS NULL AND `preferences`.`name` = 'amount' LIMIT 1
Calculator Load (0.4ms) SELECT `calculators`.* FROM `calculators` WHERE `calculators`.`id` = 574015645 LIMIT 1
SQL (0.3ms) UPDATE `adjustments` SET `amount` = 3.9 WHERE `adjustments`.`id` = 1073043801
Adjustment Load (0.6ms) SELECT `adjustments`.* FROM `adjustments` WHERE `adjustments`.`order_id` = 1069267046 AND `adjustments`.`eligible` = 1 AND (label LIKE 'Promotion%')
Payment Load (0.7ms) SELECT `payments`.* FROM `payments` WHERE `payments`.`order_id` = 1069267046 AND `payments`.`state` = 'completed'
Adjustment Load (0.5ms) SELECT `adjustments`.* FROM `adjustments` WHERE `adjustments`.`order_id` = 1069267046 AND `adjustments`.`eligible` = 1
SQL (0.4ms) UPDATE `orders` SET `shipment_state` = 'pending', `adjustment_total` = 3.9, `item_total` = 29.98, `payment_total` = 0.0, `total` = 33.88, `payment_state` = 'balance_due' WHERE `orders`.`id` = 1069267046
(0.5ms) COMMIT
(0.2ms) BEGIN
SQL (0.4ms) INSERT INTO `log_entries` (`created_at`, `details`, `source_id`, `source_type`, `updated_at`) VALUES ('2011-10-21 11:35:02', '--- !ruby/object:ActiveMerchant::Billing::PaypalExpressResponse \nauthorization: \navs_result: \n code: \n postal_match: \n street_match: \n message: \ncvv_result: \n code: \n message: \nfraud_review: false\nmessage: The transaction cannot complete successfully. Instruct the customer to use an alternative payment method.\nparams: \n Errors: \n LongMessage: The transaction cannot complete successfully. Instruct the customer to use an alternative payment method.\n SeverityCode: Error\n ShortMessage: Transaction cannot complete.\n ErrorCode: \"10417\"\n do_express_checkout_payment_response_details: \n timestamp: \"2011-10-21T11:35:00Z\"\n Version: \"62.0\"\n correlation_id: 5f6d49e448b45\n Timestamp: \"2011-10-21T11:35:00Z\"\n build: \"2183220\"\n error_codes: \"10417\"\n DoExpressCheckoutPaymentResponseDetails: \n version: \"62.0\"\n Build: \"2183220\"\n Ack: Failure\n CorrelationID: 5f6d49e448b45\n message: The transaction cannot complete successfully. Instruct the customer to use an alternative payment method.\n ack: Failure\nsuccess: false\ntest: true\n', 121, 'Payment', '2011-10-21 11:35:02')
(18.6ms) COMMIT
Completed 500 Internal Server Error in 10524ms
NoMethodError (undefined method `fail!' for #<Payment:0x105d8ec70>):
Rendered /path/to/ruby/lib/ruby/gems/1.8/gems/actionpack-3.1.1/lib/action_dispatch/middleware/templates/rescues/_trace.erb (1.9ms)
Rendered /path/to/ruby/lib/ruby/gems/1.8/gems/actionpack-3.1.1/lib/action_dispatch/middleware/templates/rescues/_request_and_response.erb (1.4ms)
Rendered /path/to/ruby/lib/ruby/gems/1.8/gems/actionpack-3.1.1/lib/action_dispatch/middleware/templates/rescues/diagnostics.erb within rescues/layout (17.0ms)