S#15539 tricky bug

S#15539 aka S#12967 aka the tricky bug

How to reproduce

To reproduce it, I have a script that follows these steps:

• restart the instance with 4 workers
• run 4 parallel requests to create 4 similar PO (1 line of a product priced 26.9e HT for 1 package of 24 items)
• check the total HT amount of each created PO
• if one is incorrect (645,60 instead of expected 26.90), stop
• otherwise, go back to first step

A few loops are enough to trigger the bug.

Observations

Versions

• Issue still occurs with latest versions available of python and psycopg2 library.
• Issue occurs more often when the instance is running with an old python version (eg 2.7.6, default on Ubuntu 14.04).
• Foodcoop's code is regularily synced with upstream. No significant recent fix spotted.

Multi-workers only

• Issue never occurs in threaded mode (workers = 0)
• Issue occurs regardless of connector's jobrunner being loaded or not.
• Usually, one worker out of 4 only computes wrong amounts. Sometimes, 2. Most of the time 0.
• A worker that computed a wrong amount will systematically compute wrong amounts. A worker that computed the correct amount will never compute wrong amounts. Practical consequence: if all workers computed amounts properly, restart instance.
• One single request on a freshly restarted instance can result in a incorrect result. Consequence: the issue is not directly caused by concurrency between workers. But it could still be favorited by the load induced by multiple workers processing requests in the same time.

Metrics

• No significant difference observed between normal vs buggy workers in terms of:

  • response time to complete PO creation request
  • consumed memory
  • cache hits

• The issue seem to occur more often when the load is high on the host.

Analysis of one case

- purchase.order:create()
 - purchase.order.line:create()

Generates an INSERT with the original product_qty (24):

INSERT INTO "purchase_order_line" ("id", "package_qty", "indicative_package", "product_uom", "date_planned", "order_id", "price_unit", "discount", "product_qty_package", "price_policy", "product_qty", "product_id", "name", "create_uid", "write_uid", "create_date", "write_date") VALUES(nextval(\'purchase_order_line_id_seq\'), 24.0, false, 1, \'2018-01-05 23:55:36\', 1992, \'26.9000\', \'0.00\', 1.0, \'package\', \'24.000\', 669, \'[70553] Filtre \xc3\xa0 th\xc3\xa9 en m\xc3\xa9tal 5 cm\', 1, 1, (now() at time zone \'UTC\'), (now() at time zone \'UTC\')) RETURNING id'

Then comes the purchase_package_qty custom code, that sets product_qty to 1 (1 package of 24 items) and recomputes amounts:

(...)
- purchase.order.line:_check_purchase_qty()
 - if pol.order_id.state

As order_id is not in the cache, a SELECT is generated, that prefetches all fields of the purchase_order_line:

SELECT "purchase_order_line"."write_uid" as "write_uid","purchase_order_line"."product_qty" as "product_qty","purchase_order_line"."account_analytic_id" as "account_analytic_id","purchase_order_line"."write_date" as "write_date","purchase_order_line"."name" as "name","purchase_order_line"."create_uid" as "create_uid","purchase_order_line"."indicative_package" as "indicative_package","purchase_order_line"."price_policy" as "price_policy","purchase_order_line"."order_id" as "order_id","purchase_order_line"."create_date" as "create_date","purchase_order_line"."discount" as "discount","purchase_order_line"."product_uom" as "product_uom","purchase_order_line"."product_qty_package" as "product_qty_package","purchase_order_line"."date_planned" as "date_planned","purchase_order_line"."price_unit" as "price_unit","purchase_order_line"."id" as "id","purchase_order_line"."package_qty" as "package_qty","purchase_order_line"."product_id" as "product_id" FROM "purchase_order_line"\n                        WHERE "purchase_order_line".id IN (79201)  ORDER BY "purchase_order_line"."id"  \n                    '

This SELECT will get the original value (24) and override the value that was in the cache (1).

Consequence : the super(PurchaseOrderLine, line)._compute_amount() will compute an incorrect amount that results in:

UPDATE "purchase_order_line" SET "price_subtotal"=645.6,"price_total"=774.72,"price_tax"=129.12,"write_uid"=1,"write_date"=(now() at time zone \'UTC\') WHERE id IN (79204)'

Note that it's not always the same recomputation that triggers the prefetching of purchase_order_line, but the result is the same.

Fix

First attempt

To avoid product_qty to be unexpectingly overriden, we locally disable prefetching:

super(PurchaseOrderLine, line.with_context(prefetch_fields=False))._compute_amount()

BUT, after testing, it turns out that this fix breaks computed.purchase.order:make_order(), that starts generating PO with TTC prices/totals at 0.

Final

We disable prefetching for product_qty only at model definition:

    product_qty = fields.Float(
        string='Quantity',
        digits=dp.get_precision('Product Unit of Measure'),
        required=True,
        _prefetch=False)