[spree-user] Re: 5 non-deterministic failures when retrieving UPS quotes (using spree_active_shipping)

On Wednesday, February 13, 2013 4:25:28 PM UTC-8, Andrew Shu wrote:

Hey all --

Seeking ideas for where to look for some bugs. This is an odd one.

I've a few sleepless nights behind me (and until I hunt this down -- I
have a few more in front of me), and I'm all out of ideas.

I gave a lot of information b/c I'm still not sure which pieces are
targeted/useful information; I'm out of active debugging leads I can follow.


*Background*

- *Problem started after an upgrades from a very old version of Spree
(before rails 3).*
- *I'd say that about 40-60% of my UPS quote requests to the server
fail, but other times I get good quotes*
- Most everything about the newest Spree (and Rails environment) is
fantastic -- but this one thing is raining on our parade!
- I develop for an online printing company for products varying from
business cards to spiral books to looseleaf copies, so we've customized the
weight calculations and shipping upcharge
- *I have currently mitigated the problem with a workaround which
decreases the risk down to about 1 failure every 100 quotes (see below)
*

*
*
*Symptoms*

- I am able to get quotes *most *of the time
- They're mostly errors caused by objects being nil when they
shouldn't be (e.g. undefined method `length' for nil:NilClass)
- The errors occur in a places where there should not be any errors
- I can test the quotes via a browser GET in my local environment.
- Request a quote; it fails
- Do nothing on the website, refresh the GET request
- New quote works with exactly same cart and zip code
- If I repeat this with a batch of 100 random zip codes, I could
get quite a few errors (some batches yield 20, others yield up to 60)
- Hence the "non-determinism" -- given the same packages and random
ZIP's, I cannot find a pattern

*

Symptom Locations
*

- Shipping quoter on the shopping cart
- Transition to "Delivery" step during checkout (where shipping is
calculated)
- Happens on both production server (CentOS), and development
environment (Windows), in both production & development mode


*Testing Mechanisms*

- A GET request that takes the cart contents, and a zipcode (embedded
in the URL), returning a map of service codes => prices
- And in the shopping cart, a javascript console script which
AJAX's the request over and over, and outputs the results
- A rails console script* (see below)* which can test UPS's Rating API
using tools from spree_active_shipping,

*
*
*Guesses at the Problem Source/My Thoughts*

- My gut says that these problems are related, but I can't prove it
- On the other hand, it's very possible it's a combination of bugs
- A fresh "re-install" of spree_active_shipping is unlikely to fix the
problem (the problem could be something else)
- I saw the threads being used in rate_hash, and I thought "hey!
randomness and threads are likely conspirators." I removed the usage of
threads. Nope -- still it.
- I saw this on Github (Database Connection Timeout & Threading
Shipping Calculation Error):
https://github.com/spree/spree/issues/2429
- I already saw the pool warning, so I upped the # of db
connections in the pool in database.yml
- Maybe it still has something to do with the threads...


*Error Locations*

Error #1:
# Top of backtrace => $project/vendor/extensions/$extension_gem/app/models/spree/line_item_decorator.rb:82:in
`weight'
# Exception => undefined method `material_dimension' for nil:NilClass
# Quick Description of Function: adds weight() to the LineItem model,
calculating weight based on option values and quantities (# sheets,
dimensions, # sides, paper type, finishing)
# Additional Comments: This exception is odd because I'm setting up
variables in this section. I'm getting which of the variant's option_values
represent the dimensions

Error #2: Most frequent
# Top of backtrace => $project/vendor/extensions/$extension_gem/app/models/spree/line_item_decorator.rb:85:in
`weight'
# Exception => undefined method `length' for nil:NilClass
# Quick Description of Function: Same as above (Error #1)
# Additional Comments: Same as above (Error #1)

Error #3: 2nd most frequent error
# Top of backtrace => $home/.rvm/gems/ruby-1.9.3-p385/gems/active_utils-1.0.5/lib/active_utils/common/posts_data.rb:56:in
`initialize'
# A few items down the stack => $home/.rvm/gems/ruby-1.9.3-p385/bundler/gems/active_shipping-2ca9ac3ea768/lib/active_shipping/shipping/carriers/ups.rb:438:in
`commit' (=> It's different in the committed file -- I added log statements
# Exception => wrong number of arguments(1 for 0)
# Quick Description of Function: This is line 438 in
active_shipping/.../ups.rb:

ssl_post("#{test ? TEST_URL : LIVE_URL}/#{RESOURCES[action]}", request)

#Also: This is line 55-57 in active_utils -- the one that actually threw
the error

def new_connection(endpoint)
Connection.new(endpoint) # Line 56. If this is referring to
ActiveMerchant::Connection, initialize() takes ONE ARGUMENT
end

Error #4:
# Top of backtrace => /vendor/extensions/$extension_gem/lib/$lib_dir/spree_active_shipping/ups_upcharge/custom.rb:9:in
`compute'
# Exception => undefined method `*' for nil:NilClass
# Quick Description of Function: Basically, define a method that can be
used to extend the various SpreeActiveShipping's UPS quotes
module SomeModule
def self.included(base)
base.class_eval do

def compute(object)
base_quote = super(object)
final = base_quote * some_constant
end
end
end
end
# Additional Notes: There are a few different upcharge mechanisms, and I
basically monkey patch Spree's UPS Calculators with these upcharge commands
# Additional Notes: Not a fan of this. Not sure if the syntax is kosher,
so I have this commented out... and things are still failing.
Error #5:
# Top of backtrace => $
bundler/gems/spree_active_shipping-c85c26bdbee3/app/models/spree/calculator/active_shipping/base.rb:22:in
`compute'
# Exception => uninitialized constant
Spree::Calculator::ActiveShipping::Base::Shipment
# Quick Description of Function: Heh, I have no clue at all why this is
failing. This should not interact with my code at all.


Error #6:
# Top of backtrace => $gems/actionpack-3.2.11/lib/action_view/path_set.rb:58:in
`find'
# Exception => Missing template shipping_quote/some_action,
spree/base/some_action, application/some_action
# Quick Description of Function: I also have no clue why this is failing.
After the shipping quotes are generated, I run:



render :text => { :keys => :values }.to_json


# I can think of no cases where ActionView would attempt to seek
an erb template


*Reproducing the Error (For me, not you.)*

- Once items are in the cart, I can POST to a URL with a zipcode, and
it'll generate a shipping quote with handling charges included.
- The POST triggers a fresh calculation via @order.rate_hash()
(assuming the zipcode/order isn't in the cache, of course)
- Given one weight, I can try a few hundred requests -- and up to 60%
of them will fail
- The errors are one the 7 that I listed above


*Rails console script to Test UPS XML Rating API*

- Rails can mostly send/recieve xml requests to UPS (with the
exception of Error #3)
- How do I know this? With the following script:

Include ActiveMerchant::Shipping

# This is the Rails console script.


#############################################################################
# spree_active_shipping\app\models\spree\calculator\ups\base.rb

#############################################################################

def carrier

carrier_details = {
:login => Spree::ActiveShipping::Config[:ups_login],
:password => Spree::ActiveShipping::Config[:ups_password],
:key => Spree::ActiveShipping::Config[:ups_key],
:test => Spree::ActiveShipping::Config[:test_mode]
}

if shipper_number = Spree::ActiveShipping::Config[:shipper_number]
carrier_details.merge!(:origin_account => shipper_number)
end
ActiveMerchant::Shipping::UPS.new(carrier_details)
end



#############################################################################
#
$project/vendor/extensions/$extension_gem/app/controllers/shipping_quote_controller.rates
(e.g. /shipping_quote/some_action?zipcode=94704)

#############################################################################
def origin
Location.new(:country => Spree::ActiveShipping::Config[:origin_country],
:city => Spree::ActiveShipping::Config[:
origin_city],
:state => Spree::ActiveShipping::Config[:
origin_state],
:zip => Spree::ActiveShipping::Config[:
origin_zip])

end

def get_quote zip, lbs
destination = Location.new(:country => "US",
:state => (zip.to_region :state => true),
:city => (zip.to_region :city => true),
:zip => zip)

packages = [Package.new(lbs * 16, [], :units => :imperial)]

carrier.find_rates(origin, destination, packages)
end

zips = ['00716', '14062', '20898', '33863', '38683', '43333', '48313',
'53577', '58581', '60180', '71213', '76012', '97308', '92127', '60606',
'20001']

zips.each do |zip|
puts "\nGetting shipping quote for Zip (#{zip}), for 20 lbs."
puts get_quote(zip, 20).inspect

end
*
*
*
*
*The Workaround: As House (the TV doctor) would say: "treat first,
diagnose later"*


#############################################################################
# $spree_core-1.2.4/app/models/spree/order.rb, changes to rate_hash

#############################################################################

def rate_hash
return @rate_hash if @rate_hash.present?

Rails.logger.info(" => spreecore => order => rate_hash => starting
calls to compute.")

# reserve one slot for each shipping method computation
computed_costs = Array.new(available_shipping_methods(:front_end).size)

# create all the threads and kick off their execution
threads = available_shipping_methods(:front_end).each_with_index.map do
Thread.new {
attempts_limit = 4
attempts = 0
computed_cost = nil

while computed_cost == nil and attempts < attempts_limit
begin
computed_costs[index] = [ship_method, ship_method.calculator.
compute(self)]
rescue Exception => e
Rails.logger.error(" <= SpreeCore <= Order <= rate_hash <=
Error on attempt: ##{attempts} of #{attempts_limit}")
Rails.logger.error(" <= SpreeCore <= Order <= rate_hash <=
(Shipping Method: #{ship_method.name})")
end
attempts += 1
end
}
end

# wait for all threads to finish
threads.map(&:join)

Rails.logger.info(" <= SpreeCore <= Order <= rate_hash <= all threads
finished.")

# now consolidate and memoize the threaded results
@rate_hash ||= computed_costs.map do |pair|
ship_method,cost = *pair
next unless cost
ShippingRate.new( :id => ship_method.id,
:shipping_method => ship_method,
:name => ship_method.name,
:cost => cost)
end.compact.sort_by { |r| r.cost }
end

*
*
*
*
Anyway, that's that.

Let me know if you want more information, or you have any notions what the
source might be.

I'll be trying to get a shipping setup on a fresh install of Spree 1.2.4.


--
Andrew