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.

[YevSent]

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

[YevSent]

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)

[YevSent]

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.