Magento2: Error 400 with braintree on checkout

[Will-I4M]

Hi,
We are facing this issue with some payment. Most of payment are successfull but sometimes it happend and we didn't figured why. If the user close the browser window and reopen it, It can solve the issue, but we do not know if it's always the case.

This issue can happend with logged in user, OR guests, and happend when user select stored card number OR, when the user give the card numbers.
It's difficult to reproduce this error, when we try to do so, it works ... but this issue happend with 10% of our clients (estimation based on logs).
When it happend, there is no exceptions in the log, even in debug mode for the braintree module.

here is some apache log lines :

XX.XX.XX.XX something.com - - [22/Mar/2017:16:02:57 +0100] "POST /rest/default/V1/guest-carts/xxxxxxxxxxxxxxxxxxxxxxxxxxxx/payment-information HTTP/1.1" 400 640 "https://something.com/checkout/" "Mozilla/5.0 (iPad; CPU OS 9_3_5 like Mac OS X) AppleWebKit/601.1.46 (KHTML, like Gecko) Version/9.0 Mobile/13G36 Safari/601.1"
XX.XX.XX.XX something.com - - [22/Mar/2017:16:03:31 +0100] "POST /rest/default/V1/guest-carts/xxxxxxxxxxxxxxxxxxxxxxxxxxxx/payment-information HTTP/1.1" 400 640 "https://something.com/checkout/" "Mozilla/5.0 (iPad; CPU OS 9_3_5 like Mac OS X) AppleWebKit/601.1.46 (KHTML, like Gecko) Version/9.0 Mobile/13G36 Safari/601.1"
XX.XX.XX.XX something.com - - [22/Mar/2017:16:03:52 +0100] "POST /rest/default/V1/guest-carts/xxxxxxxxxxxxxxxxxxxxxxxxxxxx/payment-information HTTP/1.1" 400 640 "https://something.com/checkout/" "Mozilla/5.0 (iPad; CPU OS 9_3_5 like Mac OS X) AppleWebKit/601.1.46 (KHTML, like Gecko) Version/9.0 Mobile/13G36 Safari/601.1"
XX.XX.XX.XX something.com - - [22/Mar/2017:16:03:54 +0100] "POST /rest/default/V1/guest-carts/xxxxxxxxxxxxxxxxxxxxxxxxxxxx/payment-information HTTP/1.1" 400 640 "https://something.com/checkout/" "Mozilla/5.0 (iPad; CPU OS 9_3_5 like Mac OS X) AppleWebKit/601.1.46 (KHTML, like Gecko) Version/9.0 Mobile/13G36 Safari/601.1"
XX.XX.XX.XX something.com - - [22/Mar/2017:16:04:45 +0100] "POST /rest/default/V1/guest-carts/xxxxxxxxxxxxxxxxxxxxxxxxxxxx/payment-information HTTP/1.1" 400 640 "https://something.com/checkout/" "Mozilla/5.0 (iPad; CPU OS 9_3_5 like Mac OS X) AppleWebKit/601.1.46 (KHTML, like Gecko) Version/9.0 Mobile/13G36 Safari/601.1"
XX.XX.XX.XX something.com - - [22/Mar/2017:16:05:04 +0100] "POST /rest/default/V1/guest-carts/xxxxxxxxxxxxxxxxxxxxxxxxxxxx/payment-information HTTP/1.1" 400 640 "https://something.com/checkout/" "Mozilla/5.0 (iPad; CPU OS 9_3_5 like Mac OS X) AppleWebKit/601.1.46 (KHTML, like Gecko) Version/9.0 Mobile/13G36 Safari/601.1"

With this client using Edge :

xx.xx.xx.xx something.com - - [21/Mar/2017:18:12:35 +0100] "POST /rest/default/V1/carts/mine/payment-information HTTP/1.1" 400 4018 "https://something.com/checkout/" "Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/51.0.2704.79 Safari/537.36 Edge/14.14393"
xx.xx.xx.xx something.com - - [21/Mar/2017:18:13:46 +0100] "POST /rest/default/V1/carts/mine/payment-information HTTP/1.1" 400 610 "https://something.com/checkout/" "Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/51.0.2704.79 Safari/537.36 Edge/14.14393"
xx.xx.xx.xx something.com - - [21/Mar/2017:18:14:58 +0100] "POST /rest/default/V1/carts/mine/payment-information HTTP/1.1" 400 610 "https://something.com/checkout/" "Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/51.0.2704.79 Safari/537.36 Edge/14.14393"
xx.xx.xx.xx something.com - - [21/Mar/2017:18:15:28 +0100] "POST /rest/default/V1/carts/mine/payment-information HTTP/1.1" 400 610 "https://something.com/checkout/" "Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/51.0.2704.79 Safari/537.36 Edge/14.14393"

4 unsuccessfull payment

Here the client tried to close the browser window, reopen it, re log and retry payment :
xx.xx.xx.xx something.com - - [21/Mar/2017:18:18:34 +0100] "POST /rest/default/V1/carts/mine/payment-information HTTP/1.1" 200 501 "https://something.com/checkout/" "Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/51.0.2704.79 Safari/537.36 Edge/14.14393"
This time it was good.

Preconditions

Environement : Debian 8 / PHP 7 / Magento 2.1.2 / Redis for sessions and FPC / Opcache
Mysql : mysqlnd 5.0.12-dev / mysqld 5.7.16
Apache : Server version: Apache/2.4.10 (Debian)

Steps to reproduce

As you can see in the log, this happend when the client click on the "Proceed payment button", but it's really hard for us to reproduce it, its random.

Expected result

1. Payment OK or KO

Actual result

1. Logs as written here, no exceptions, no i/o with the braintree servers/

Thanks for your help.

[Will-I4M]

We have a lot of http/400 this morning, could you tell me where can I add lines in the code in order to log more things and understand the reason of this 400 ?
Thanks for your time and involvement.

[joni-jones]

At first, need to get transaction details from debug log.

To find original reason of fails, you can use xdebug and set breakpoints in the https://github.com/magento/magento2/blob/2.1/app/code/Magento/Checkout/Model/GuestPaymentInformationManagement.php#L83 and https://github.com/magento/magento2/blob/2.1/app/code/Magento/Checkout/Model/PaymentInformationManagement.php#L71 or can use a logger to find original reason of failing like in https://github.com/magento/magento2/blob/develop/app/code/Magento/Checkout/Model/PaymentInformationManagement.php#L90

[Will-I4M]

Usually, when this issue happend, there is nothing in the debug.log and there is nothing in the transaction log in the braintree backend. I'll add a logger to get more informations.

I discovered this morning that the two http / 400 are another issue. This time, there is line written in the debug.log. Payment where accepted, but there were no sales recorded in the sales history (magento), confirmation mail is not sent. There is lines for that transaction in the debug.log. it's maybe preferable that I open a different issue ?
Where can I put interesting lines comming from the debug.log ?
Thanks for your time

[Will-I4M]

@joni-jones Just to be sure, this server is in production, I can't switch it into dev mode, to much traffic. The code is compiled, could you tell me where can I find those files :

https://github.com/magento/magento2/blob/2.1/app/code/Magento/Checkout/Model/GuestPaymentInformationManagement.php#L83 and https://github.com/magento/magento2/blob/2.1/app/code/Magento/Checkout/Model/PaymentInformationManagement.php#L71 or can use a logger to find original reason of failing like in https://github.com/magento/magento2/blob/develop/app/code/Magento/Checkout/Model/PaymentInformationManagement.php#L90

[joni-jones]

This classes should be in vendor/magento, but if you change them and run composer-update again these files will be overwritten.

[Will-I4M]

For the first issue (error http 400, without transaction in the braintree history, and in sale history). Something is going wrong in vendor/magento/module-quote/Model/QuoteManagement.php

In the function protected function submitQuote(QuoteEntity $quote, $orderData = [])

I added some error_log calls (I know it's not the best way)

   ```
   error_log("QuoteMAnagement.php : SUBMITTING QUOTE") ; 

    $order = $this->orderFactory->create();
    $this->quoteValidator->validateBeforeSubmit($quote) ;
    if (!$quote->getCustomerIsGuest()) 
    {
        if ($quote->getCustomerId()) {
            $this->_prepareCustomerQuote($quote);
        }
        $this->customerManagement->populateCustomerInfo($quote);
    }
    $addresses = [];

// When error 400 happend, it never reach this step :

    error_log("QuoteMAnagement.php : RESERVING ORDER") ;

 $quote->reserveOrderId();
        error_log("QuoteMAnagement.php : ORDER RESERVED") ; 

        if ($quote->isVirtual()) 
        {
            $this->dataObjectHelper->mergeDataObjects(
                '\Magento\Sales\Api\Data\OrderInterface',
                $order,
                $this->quoteAddressToOrder->convert($quote->getBillingAddress(), $orderData)
            );
        } 
..........

Nothing in the exception.log, nothing in debug.log
In this case, here is the apache log :

88.127.XX.XX something.com - - [01/Apr/2017:12:29:03 +0200] "POST /rest/default/V1/guest-carts/d073e814b5ec4f865c8f9afd71a5b2e7/payment-information HTTP/1.1" 400 4016 "https://something.com/checkout/" "Mozilla/5.0 (Windows NT 10.0; WOW64; rv:52.0) Gecko/20100101 Firefox/52.0"
88.127.XX.XX something.com - - [01/Apr/2017:12:29:18 +0200] "POST /rest/default/V1/guest-carts/d073e814b5ec4f865c8f9afd71a5b2e7/payment-information HTTP/1.1" 400 4016 "https://something.com/checkout/" "Mozilla/5.0 (Windows NT 10.0; WOW64; rv:52.0) Gecko/20100101 Firefox/52.0"
88.127.XX.XX something.com - - [01/Apr/2017:12:29:26 +0200] "POST /rest/default/V1/guest-carts/d073e814b5ec4f865c8f9afd71a5b2e7/payment-information HTTP/1.1" 400 4016 "https://something.com/checkout/" "Mozilla/5.0 (Windows NT 10.0; WOW64; rv:52.0) Gecko/20100101 Firefox/52.0"

The guy is triying one hour later : 

88.127.XX.XX something.com - - [01/Apr/2017:13:58:35 +0200] "POST /rest/default/V1/guest-carts/d073e814b5ec4f865c8f9afd71a5b2e7/payment-information HTTP/1.1" 400 4016 "https://something.com/checkout/" "Mozilla/5.0 (Windows NT 10.0; WOW64; rv:52.0) Gecko/20100101 Firefox/52.0"

I Didn't sorted this out for now. If someone has an idea..

[Will-I4M]

@joni-jones
I can now reproduce this issue by myself, as a logged in user, using the stored card number (braintree).

If I comment this part :

  if (!$quote->getCustomerIsGuest()) 
    {
        if ($quote->getCustomerId()) {
            $this->_prepareCustomerQuote($quote);
        }
        $this->customerManagement->populateCustomerInfo($quote);
    }

The payment is successfull and no error 400, but if I uncomment it and retry, I get an error 400.
I let the page openend, re comment this part, reset the opcache, and retried and the payment is successful again, no error 400.

I did this modification :

    $guest = $quote->getCustomerIsGuest() ; 
        error_log("USER IS GUEST : $guest") ; 
        $valid_customer = 0 ; 

        if($guest < 1)
            $valid_customer = 1 ; 

        if ($valid_customer == 1) 
        {
        if ($quote->getCustomerId()) {
            $this->_prepareCustomerQuote($quote);
        }
        $this->customerManagement->populateCustomerInfo($quote);
    }
.....

And again, payment successfull, no error 400.
I do not understand the difference. getCustomerIsGuest() is returning in my case '0', do you think this is related to opcache or sessions ?
In the original code It seems the process die just after this line : if (!$quote->getCustomerIsGuest())

Version of php :
Zend Engine v3.0.0, Copyright (c) 1998-2016 Zend Technologie with Zend OPcache v7.0.12-1~dotdeb+8.1, Copyright (c)

[joni-jones]

You need to log original exception message, from https://github.com/magento/magento2/blob/2.1/app/code/Magento/Checkout/Model/GuestPaymentInformationManagement.php#L83 and https://github.com/magento/magento2/blob/2.1/app/code/Magento/Checkout/Model/PaymentInformationManagement.php#L71 these two points where you can catch all exceptions, even if fails quote management, it much easier to find at first original exception message and then find an issue in the source code.

If you are using error_log, all messages you can find in the apache ssl_error_log or error_log depends on SSL configuration for your application. If you want to see messages in Magento debug or exception logs, you need to use Magento logger based on \Psr\Log\LoggerInterface.

[Will-I4M]

OK, I added " $this->getLogger()->critical($e);" at :
https://github.com/magento/magento2/blob/2.1/app/code/Magento/Checkout/Model/GuestPaymentInformationManagement.php#L83 and https://github.com/magento/magento2/blob/2.1/app/code/Magento/Checkout/Model/PaymentInformationManagement.php#L71

Today, a lot of errors, this time the script exited 3 times between
this line : $order = $this->orderFactory->create();
and this line : $this->quoteValidator->validateBeforeSubmit($quote) ;
in the submitQuote function (QuoteManagement.php), without exception in the exception.log / or line in debug.log.

Another bug (not the same) is present in the checkout process, but it trigger rarely. In this other bug, the payment is OK and appear in the braintree history but the order is not present in the sale history.
In that case, there is nothing in the exception.log, but there is lines in the debug.log. It happend in the try/catch block of the submmitQuote function in QuoteManagement.php. I added a logger in this section too, will propably get more informations on this next time.

[scottsb]

To the latter point, this is an architectural concern I also have: if there is an exception in processing the payment after it is captured, the handling structure causes the order not to be created and the user to be taken back to the payment form. This is obviously a major customer service issue, but since exceptions should be, well, exceptional, it's hard to argue it's strictly a bug.

[Will-I4M]

@scottsb I understand your point of view, but this kind of situations are critical, because you need to check every transactions in order to see if one of them has been "forgotten" in the sales list. I think that once the payment has been accepted, even if there is an exception in the process, an order should be created (even with minimal informations), or notified (mail if it's not possible to write in db).

[scottsb]

I'd certainly not argue if the Magento gods look upon this kindly to change. ;-)

[opepin]

Agreed - that's no ok to lose exceptions if the order cannot be save, specially after payment.

Actually the logs @joni-jones is suggesting (which are today the only way to know what's going on besides xdebug) are in develop branch, apparently part of a 2.2-dev ticket (MAGETWO-60073).
https://github.com/magento/magento2/blame/develop/app/code/Magento/Checkout/Model/GuestPaymentInformationManagement.php#L96
https://github.com/magento/magento2/blame/develop/app/code/Magento/Checkout/Model/PaymentInformationManagement.php#L90

That's a good candidate for 2.1.7 or a patch, seeing the number of different bugs where people are puzzled with similar "400", and no exceptions in log : https://github.com/magento/magento2/issues/8488 https://github.com/magento/magento2/issues/6929 https://github.com/magento/magento2/issues/5902 https://github.com/magento/magento2/issues/6125 https://github.com/magento/magento2/issues/6522 https://github.com/magento/magento2/issues/9116

[Will-I4M]

I followed @joni-jones suggestions, but this error did not happend since I added log lines. Just one time because of "incorrect address" according to the logs, but the shipping address was correct. I added some more check point (log ...), and I'm waiting for more data.
At this point, I think there is a lot of different scenarios in wich error 400 could happend (more than 10 shipping address, billing address, order Id, customer ic, customer adress Id ....). This part should be refactored ..

[Will-I4M]

Here is an error messages logged into exception.log after some error 400 (4 times today) :

Integrity constraint violation: 1062 Duplicate entry '000000898-1' for key 'SALES_ORDER_INCREMENT_ID_STORE_ID', query was: INSERT INTO sales_order (state, status, protect_code, shipping_description, is_virtual, store_id, customer_id, base_discount_amount, base_discount_invoiced, base_grand_total, base_shipping_amount, base_shipping_invoiced, base_shipping_tax_amount, base_subtotal, base_subtotal_invoiced, base_tax_amount, base_tax_invoiced, base_to_global_rate, base_to_order_rate, base_total_invoiced, base_total_invoiced_cost, base_total_paid, discount_amount, discount_invoiced, grand_total, shipping_amount, shipping_invoiced, shipping_tax_amount, store_to_base_rate, store_to_order_rate, subtotal, subtotal_invoiced, tax_amount, tax_invoiced, total_invoiced, total_paid, total_qty_ordered, customer_is_guest, customer_note_notify, customer_group_id, quote_id, base_shipping_discount_amount, base_subtotal_incl_tax, base_total_due, shipping_discount_amount, subtotal_incl_tax, total_due, weight, increment_id, applied_rule_ids, base_currency_code, customer_email, customer_firstname, customer_lastname, customer_middlename, discount_description, global_currency_code, order_currency_code, remote_ip, shipping_method, store_currency_code, store_name, total_item_count, discount_tax_compensation_amount, base_discount_tax_compensation_amount, shipping_discount_tax_compensation_amount, discount_tax_compensation_invoiced, base_discount_tax_compensation_invoiced, shipping_incl_tax, base_shipping_incl_tax, gift_message_id) VALUES (?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?) in /var/www/xxxxxxxxx/vendor/magento/zendframework1/library/Zend/Db/Statement/Pdo.php:235

I don't know how to prevent this issue. The payment is accepted (4 times by credit card, that I must refund now ..) but there is no records in the sales list.

[stephenkidwell]

Anyone know if this issue has been resolved? I can't find a reference in any recent release.

[magento-engcom-team]

The issue already fixed in 2.2.0
@Will-I4M thank you for report