Openfoodnetwork: Paypal intermittently working

[lin-d-hop]

Description

Paypal is failing on the latest release.

Add the credentials in the backend.
Then on checkout we see the slug.

This is the same error we see when the credentials for paypal are incorrect. I tested on two enterprises and Rachel tested on the enterprise she set up for the last release. We get the slug every time - 500 error.

https://app.bugsnag.com/open-food-france/open-food-france-prod/errors/5f22ba8413318a0017354215?filters[event.since][0][type]=eq&filters[event.since][0][value]=30d&filters[error.status][0][type]=eq&filters[error.status][0][value]=open&filters[app.release_stage][0][value]=staging&filters[app.release_stage][0][type]=eq

Expected Behavior

When choosing to pay by paypal the shopper should be redirected at checkout

Actual Behaviour

Redirection fails with 500 error and the user sees the slug.

Steps to Reproduce

1. Set up paypal payment method for an enterprise
2. Checkout in the shop using this payment method
3. SLUG

Animated Gif/Screenshot

We all know what the slug looks like

Workaround

None. Release blocked!

Severity

bug-s1: a critical feature is broken: checkout, payments, signup, login

Your Environment

• Version used: 3.2.1
• Browser name and version: Chrome
• Operating System and version (desktop or mobile): Linux Desktop

Possible Fix

[sauloperez]

I can't find the FR staging Bugsnag neither in FR's Bugsnag account nor in AU's one. We might be missing it? For the record then, this is the exception from the logs:

I, [2020-08-03 12:11:50#23243]  INFO -- : Started PUT "/checkout.json" for 46.172.229.193 at 2020-08-03 12:11:50 +0200
I, [2020-08-03 12:11:50#23243]  INFO -- : Processing by CheckoutController#update as JSON
I, [2020-08-03 12:11:50#23243]  INFO -- :   Parameters: {"order"=>{"default_bill_address"=>false, "default_ship_address"=>false, "email"=>"[email protected]", "shipping_method_id"=>31, "payments_attributes"=>[{"payment_method_id"=>"112"}], "bill_address_attributes"=>{"zipcode"=>"4450-783", "city"=>"Matosinhos", "state_name"=>"09", "state_id"=>63, "phone"=>"[phone]", "firstname"=>"Luis", "lastname"=>"Ramos", "address1"=>"Rua Santos Lessa 31, 2o esq", "address2"=>"Matosinhos, Porto, Portugal", "country_id"=>13, "country_name"=>"France"}, "ship_address_attributes"=>{"zipcode"=>"4450-783", "city"=>"Matosinhos", "state_name"=>"09", "state_id"=>63, "phone"=>"[phone]", "firstname"=>"Luis", "lastname"=>"Ramos", "address1"=>"Rua Santos Lessa 31, 2o esq", "address2"=>"Matosinhos, Porto, Portugal", "country_id"=>13, "country_name"=>"France"}}, "checkout"=>{"order"=>{"default_bill_address"=>false, "default_ship_address"=>false, "email"=>"[email protected]", "shipping_method_id"=>31, "payments_attributes"=>[{"payment_method_id"=>"112"}], "bill_address_attributes"=>{"zipcode"=>"4450-783", "city"=>"Matosinhos", "state_name"=>"09", "state_id"=>63, "phone"=>"[phone]", "firstname"=>"Luis", "lastname"=>"Ramos", "address1"=>"Rua Santos Lessa 31, 2o esq", "address2"=>"Matosinhos, Porto, Portugal", "country_id"=>13, "country_name"=>"France"}, "ship_address_attributes"=>{"zipcode"=>"4450-783", "city"=>"Matosinhos", "state_name"=>"09", "state_id"=>63, "phone"=>"[phone]", "firstname"=>"Luis", "lastname"=>"Ramos", "address1"=>"Rua Santos Lessa 31, 2o esq", "address2"=>"Matosinhos, Porto, Portugal", "country_id"=>13, "country_name"=>"France"}}}}
I, [2020-08-03 12:11:51#23243]  INFO -- : Completed 200 OK in 841ms (Views: 0.3ms | ActiveRecord: 181.5ms)
I, [2020-08-03 12:11:52#23240]  INFO -- : Started GET "/paypal?payment_method_id=112" for 46.172.229.193 at 2020-08-03 12:11:52 +0200
I, [2020-08-03 12:11:52#23240]  INFO -- : Processing by Spree::PaypalController#express as HTML
I, [2020-08-03 12:11:52#23240]  INFO -- :   Parameters: {"payment_method_id"=>"112"}
I, [2020-08-03 12:11:52#23240]  INFO -- : Completed 500 Internal Server Error in 638ms
I, [2020-08-03 12:11:52#23240]  INFO -- [Bugsnag]: Notifying https://notify.bugsnag.com of OpenSSL::SSL::SSLError
F, [2020-08-03 12:11:52#23240] FATAL -- :
OpenSSL::SSL::SSLError (SSL_connect returned=1 errno=0 state=error: certificate verify failed):
  /home/openfoodnetwork/.rbenv/versions/2.3.7/lib/ruby/2.3.0/net/protocol.rb:44:in `connect_nonblock'
  /home/openfoodnetwork/.rbenv/versions/2.3.7/lib/ruby/2.3.0/net/protocol.rb:44:in `ssl_socket_connect'
  /home/openfoodnetwork/.rbenv/versions/2.3.7/lib/ruby/2.3.0/net/http.rb:928:in `connect'
  /home/openfoodnetwork/.rbenv/versions/2.3.7/lib/ruby/2.3.0/net/http.rb:863:in `do_start'
  /home/openfoodnetwork/.rbenv/versions/2.3.7/lib/ruby/2.3.0/net/http.rb:852:in `start'
  paypal-sdk-core (0.2.10) lib/paypal-sdk/core/util/http_helper.rb:64:in `block in http_call'
  paypal-sdk-core (0.2.10) lib/paypal-sdk/core/util/http_helper.rb:80:in `log_http_call'
  paypal-sdk-core (0.2.10) lib/paypal-sdk/core/api/merchant.rb:102:in `log_http_call'
  paypal-sdk-core (0.2.10) lib/paypal-sdk/core/util/http_helper.rb:62:in `http_call'
  paypal-sdk-core (0.2.10) lib/paypal-sdk/core/api/base.rb:84:in `api_call'
  paypal-sdk-core (0.2.10) lib/paypal-sdk/core/api/base.rb:96:in `post'
  paypal-sdk-merchant (1.106.1) lib/paypal-sdk/merchant/services.rb:568:in `SetExpressCheckout'
  /home/openfoodnetwork/.gem/ruby/2.3.0/bundler/gems/better_spree_paypal_express-e28e4a8c5ced/app/controllers/spree/paypal_controller.rb:36:in `express'
  actionpack (4.0.13) lib/action_controller/metal/implicit_render.rb:4:in `send_action'
  actionpack (4.0.13) lib/abstract_controller/base.rb:189:in `process_action'
  actionpack (4.0.13) lib/action_controller/metal/rendering.rb:10:in `process_action'
  actionpack (4.0.13) lib/abstract_controller/callbacks.rb:18:in `block in process_action'
  activesupport (4.0.13) lib/active_support/callbacks.rb:503:in `_run__1943850445740684969__process_action__callbacks'
  activesupport (4.0.13) lib/active_support/callbacks.rb:80:in `run_callbacks'
  actionpack (4.0.13) lib/abstract_controller/callbacks.rb:17:in `process_action'
  actionpack (4.0.13) lib/action_controller/metal/rescue.rb:29:in `process_action'
  actionpack (4.0.13) lib/action_controller/metal/instrumentation.rb:31:in `block in process_action'
  activesupport (4.0.13) lib/active_support/notifications.rb:159:in `block in instrument'
  activesupport (4.0.13) lib/active_support/notifications/instrumenter.rb:20:in `instrument'
  activesupport (4.0.13) lib/active_support/notifications.rb:159:in `instrument'
  actionpack (4.0.13) lib/action_controller/metal/instrumentation.rb:30:in `process_action'
  actionpack (4.0.13) lib/action_controller/metal/params_wrapper.rb:250:in `process_action'
  activerecord (4.0.13) lib/active_record/railties/controller_runtime.rb:18:in `process_action'
  actionpack (4.0.13) lib/abstract_controller/base.rb:136:in `process'
  actionpack (4.0.13) lib/abstract_controller/rendering.rb:44:in `process'
  actionpack (4.0.13) lib/action_controller/metal.rb:195:in `dispatch'
  actionpack (4.0.13) lib/action_controller/metal/rack_delegation.rb:13:in `dispatch'
  actionpack (4.0.13) lib/action_controller/metal.rb:231:in `block in action'

[RachL]

@sauloperez are you sure it's not in the FR account? We have bugsnag alerts for FR staging on slack so they must be somewhere :)

[RachL]

@sauloperez see https://openfoodnetwork.slack.com/archives/CEF14NU3V/p1596445585449300

[sauloperez]

nevermind, the fact that the project is called Open Food France Prod got me confused :see_no_evil:

[RachL]

@sauloperez ah yes it confused me often as well. Any idea if we can change this / why we did it this way?

[sauloperez]

I just did :sunglasses: I was probably opened without knowing it had support for multiple environments.

[sauloperez]

Given @lin-d-hop tested the release in both UK and FR and @RachL checked the last released worked, I think the issue is that PayPal changed their SSL cert on their end and that's why we get an SSL_connect returned=1 errno=0 state=error: certificate verify failed.

I read a number of reports in Stackoverflow and https://www.paypal.com/in/webapps/mpp/ssl-upgrade about PayPal changing their certs but I don't know the exact dates. Our deprecated PayPal client includes the certs within the gem, so if they changed on their side ours will fail, and it looks like it. However, the fact that we haven't heard from any enterprises with failed PayPal payments leads us to think this is only related to the sandbox endpoint.

I haven't investigated whether this is all due to a change included in this release but it doesn't look like that.

[luisramos0]

Pau that SSL change is from 2016:

Are we 100% sure this was introduced by this release or shall we deploy the previous OFN version to some staging server and try again?

[luisramos0]

I am moving this conversation to Slack so we can move faster today.

[luisramos0]

So far we have found paypal is broken in staging even with previous version v3.2.0
Paypal was last successfully tested in staging in the last release testing (around one week ago?).
I have verified Paypal is working in UK live (on v2.10.1) and also in AUS live (on v3.2.0).

This takes us to either:

• a change in the certificates on paypal's sandboxes
• an old certificate on our code somewhere, for example, this 8 year old certificate here https://github.com/paypal/sdk-core-ruby/blob/master/data/paypal.crt

[luisramos0]

I manually removed the certificate file included in paypal-sdk-core-0.2.10/data/paypal.crt from /home/openfoodnetwork/.gem/ruby/2.3.0/gems
Restarted unicorn but the error persists.

[luisramos0]

After further investigation we decided to release and deploy to Katuma live where we could test Paypal.
We deployed v3.2.1. to Katuma live and it all looks good and I was able to collect a real Paypal payment in Katuma live.
That means this is not blocking the release anymore.

This looks like a problem with certificates on the staging servers or our dependencies and their interaction with the paypal sandboox API.
We concluded we should upgrade the paypal sdk code. We should create a separate issue for that.
But we are not sure an upgrade will fix this issue so we need to keep this issue open.

I am going to remove the label S1 as this is not a prod issue but we need to fix this, not being able to test paypal in staging is a big risk for the integration. Do you agree?

[luisramos0]

Paypal integration upgrade. Issue created: https://github.com/openfoodfoundation/openfoodnetwork/issues/5857

[sauloperez]

Good call guys :clap: !

[sauloperez]

I manually removed the certificate file included in paypal-sdk-core-0.2.10/data/paypal.crt from /home/openfoodnetwork/.gem/ruby/2.3.0/gems
Restarted unicorn but the error persists.

:hankey: that then rules out my hypothesis that then the OS's CA certificates would take precedence and requests would validate :see_no_evil:

[sauloperez]

The issue is still happening. I got the same stacktrace from FR staging. It seems that the page we need to watch is https://www.paypal-status.com/history/production. Looks like https://www.paypal-status.com/history/eventdetails/14201 is what we hit? Following the thread, I found what is affecting us: https://nakedsecurity.sophos.com/2020/07/13/digicert-revokes-a-raft-of-web-security-certificates/. When I run:

$ openssl s_client -connect api.sandbox.paypal.com:443
(lots of output)
---                                                                                             
Certificate chain                       
 0 s:/C=US/ST=California/L=San Jose/O=PayPal, Inc./OU=PayPal Production/CN=api.paypal.com
   i:/C=US/O=DigiCert Inc/CN=DigiCert Global CA G2                                          
 1 s:/C=US/O=DigiCert Inc/CN=DigiCert Global CA G2  
   i:/C=US/O=DigiCert Inc/OU=www.digicert.com/CN=DigiCert Global Root G2                                                                                                                        
 2 s:/C=US/O=DigiCert Inc/OU=www.digicert.com/CN=DigiCert Global Root G2
   i:/C=US/O=VeriSign, Inc./OU=VeriSign Trust Network/OU=(c) 2006 VeriSign, Inc. - For authorized use only/CN=VeriSign Class 3 Public Primary Certification Authority - G5
---                 
(lots more output)
---
New, TLSv1/SSLv3, Cipher is xxx
(...)
SSL-Session:
    Protocol  : TLSv1.2
    (...)
    Start Time: 1596538975
    Timeout   : 300 (sec)
    Verify return code: 0 (ok)
---

DigiCert Global CA G2 matches the first one on the list of affected certs at https://nakedsecurity.sophos.com/2020/07/13/digicert-revokes-a-raft-of-web-security-certificates/. With slightly different output the same cert is listed when running openssl s_client -connect api.paypal.com:443.

By https://knowledge.digicert.com/alerts/DigiCert-ICA-Replacement looks like the solution is to have our PayPal integration use the cert DigiCert EV RSA CA G2 which can be downloaded from that same page.

[sauloperez]

I've been trying to get paypal-sdk to read the DigiCert EV RSA CA G2.cer file linked in https://knowledge.digicert.com/alerts/DigiCert-ICA-Replacement without success. It seems that's not the kind of file we need because it just fails with OpenSSL::PKey::RSAError: Neither PUB key nor PRIV key: nested asn1 error. It should be a *.pem instead.

Then, I tried with the testing .pem file I found in paypal-sdk at spec/config/cert_key.pem and it seemed to work. I have to double check that though because it also worked without it:

irb(main):009:0> PayPal::SDK::Core::Config.config   
=> #<PayPal::SDK::Core::Config:0x0000555b62ca41e0 @client_id="EBWKjlELKMYqRNQ6sYvFo64FtaRLRR5BdHEESmha49TM", @client_secret="EO422dn3gQLgDbuwqTjzrFgFtaRLRR5BdHEESmha49TM", @mode="sandbox", @app_id="APP-80W284485P519543T", @username="jb-us-seller_api1.paypal.com", @password="WX4WTU3S8MY44S7F", @signature="AFcWxV21C7fd0v3bYYYRCpSSRl31A7yDhhsPUU2XhtMoZXsWHFxu-RWy", @cert_path="config/cert_key.pem", @sandbox_email_address="[email protected]", @ssl_options={}>
irb(main):010:0> PayPal::SDK::Core::Config.set_config(:cert_path => nil)
=> #<PayPal::SDK::Core::Config:0x0000555b62ca41e0 @client_id="EBWKjlELKMYqRNQ6sYvFo64FtaRLRR5BdHEESmha49TM", @client_secret="EO422dn3gQLgDbuwqTjzrFgFtaRLRR5BdHEESmha49TM", @mode="sandbox", @app_id="APP-80W284485P519543T", @username="jb-us-seller_api1.paypal.com", @password="WX4WTU3S8MY44S7F", @signature="AFcWxV21C7fd0v3bYYYRCpSSRl31A7yDhhsPUU2XhtMoZXsWHFxu-RWy", @cert_path=nil, @sandbox_email_address="[email protected]", @ssl_options={}>
irb(main):011:0> http = create_http_connection(URI('https://api.paypal.com'))
=> #<Net::HTTP api.paypal.com:443 open=false>
irb(main):012:0> http.start
=> #<Net::HTTP api.paypal.com:443 open=true>

What I get from FR staging is a bit confusing though

irb(main):002:0> http = create_http_connection(URI('https://api.paypal.com'))=> #<Net::HTTP api.paypal.com:443 open=false>irb(main):003:0> http.start
=> #<Net::HTTP api.paypal.com:443 open=true>
irb(main):004:0> http = create_http_connection(URI('https://api-3t.sandbox.paypal.com/2.0/'))
=> #<Net::HTTP api-3t.sandbox.paypal.com:443 open=false>
irb(main):005:0> http.start
OpenSSL::SSL::SSLError: SSL_connect returned=1 errno=0 state=error: certificate verify failed
        from /home/openfoodnetwork/.rbenv/versions/2.3.7/lib/ruby/2.3.0/net/protocol.rb:44:in `connect_nonblock'
(...)
irb(main):007:0> http = create_http_connection(URI('https://api.sandbox.paypal.com'))
=> #<Net::HTTP api.sandbox.paypal.com:443 open=false>irb(main):008:0> http.startOpenSSL::SSL::SSLError: SSL_connect returned=1 errno=0 state=error: certificate verify failed
        from /home/openfoodnetwork/.rbenv/versions/2.3.7/lib/ruby/2.3.0/net/protocol.rb:44:in `connect_nonblock'
        from /home/openfoodnetwork/.rbenv/versions/2.3.7/lib/ruby/2.3.0/net/protocol.rb:44:in `ssl_socket_connect'

Productio works, at least this time. It could as well be leftovers from my hacks that make it work :man_shrugging:

Also, I still need to investigate where should the config/paypal.rb (here is where we define a cert_path of our own) and config/initializers/paypal.rb be. In our app or maybe in better_spree_paypal_express or even in merchant-sdk-ruby? What's clear is that they are not in this repo. Then, we could know by which mechanism are SSL requests being verified with so far. paypal-sdk deals with certs but also with a signature. See lib/paypal-sdk/core/config.rb:96. This step will help us understand how our PayPal integration works and most importantly, how it needs to be upgraded.

[sauloperez]

I found the solution! :tada: We need to make the PayPal SDK stop specifying the CA file the gem brings. This effectively lets the OpenSSL lib to rely on Ubuntu's CA certs, which are kept up to date by package upgrades (I'm assuming. I haven't checked that far). Requests to sandbox now go through.

If for some reason this doesn't work, we can still pass cert_path in the configuration so that the SSL settings of the Net::HTTP object is configured using a PEM certificate we provide. Check out the example SSL/HTTPS request with PEM certificate at http://www.rubyinside.com/nethttp-cheat-sheet-2940.html.

Meanwhile, I found out :point_down:

How the PayPal integration works (WIP)

In the better_spree_paypal_express gem, Gateway::PayPalExpress has all payment method credentials, including the signature, as spree preferences that the user provides in /admin taken from their PayPal account (explained in the gem's README). The gem itself provides a controller and the Spree::Gateway glue to talk to PayPal's Ruby Merchant API.

To check out these preferences you can run the following query:

SELECT *                                                                                        
  FROM spree_preferences
 WHERE key ILIKE '%/spree/gateway/pay_pal_express/%/<payment_method_id>'

From this gem, PayPal's SDK is configured without the need for a config/paypal.yml every time #provider is called. That is, each request is authenticated separately with each PayPal payment method's credentials although configuration is shared across the entire SDK. These credentials are used as the value for SOAP_AUTH_HEADER in paypal-sdk-core-0.2.10/lib/paypal-sdk/core/api/merchant.rb as the mean of API authentication. Note this has nothing to do with the lower level SSL handshake and its verification step. They are two separate worlds: SOAP API and HTTP and SSL.

The Net::HTTP instance is configured for SSL in paypal-sdk-core-0.2.10/lib/paypal-sdk/core/util/http_helper.rb:42. There #default_ca_file goes find data/paypal.crt to be used as the request ca_file.

[lin-d-hop]

Sir, you are a genius.

Actually, I much prefer the idea that genius lives outside of us and comes to visit sometimes.

Sir, you had a genius :-)

[sauloperez]

I'd say there was a window of focus and patience, which doesn't happen often, unfortunately.

[luisramos0]

Nice, so your original clue was right! How do you explain that that first test where I remove the paypal.crt file didnt work?

[sauloperez]

I still don't know. I guess it would have failed due to the file not being found. Did you reboot Unicorn?

[luisramos0]

yes, I rebooted unicorn. but yes, maybe it has failed due to the file not being found :+1: