Failures when recording tests in saleor

[apotterri]

As of https://github.com/saleor/saleor/commit/38df90a67 (i.e. when it was still using Django 3.2), most of the tests ran properly and generated AppMaps. 12 of them failed, however, because running with the agent attached caused extra SQL queries.

Details of the failures: appmap-failures.log.zip

[symwell]

To start debugging this, I get three failures with

APPMAP=true py.test -s -v saleor/warehouse/

=========================================================================== short test summary info ============================================================================
FAILED saleor/warehouse/tests/test_preorder_reservations_management.py::test_preorder_reservation_fails_if_global_threshold_was_allocated - Failed: DID NOT RAISE <class 'sal...
FAILED saleor/warehouse/tests/test_preorder_reservations_management.py::test_preorder_reservation_fails_if_channel_threshold_was_reserved - Failed: DID NOT RAISE <class 'sal...
FAILED saleor/warehouse/tests/test_preorder_reservations_management.py::test_preorder_reservation_fails_if_global_threshold_was_reserved - Failed: DID NOT RAISE <class 'sale...
============================================================ 3 failed, 103 passed, 9 warnings in 309.49s (0:05:09) =============================================================

It seems to be related to pytest.raises

        with pytest.raises(InsufficientStock):
>           reserve_preorders(
                [checkout_line],
                [checkout_line.variant],
                COUNTRY_CODE,
                channel_USD.slug,
                RESERVATION_LENGTH,
            )
E           Failed: DID NOT RAISE <class 'saleor.core.exceptions.InsufficientStock'>

[symwell]

The zip with details of the failures contains

saleor/graphql/checkout/tests/benchmark/test_checkout_mutations.py:395:
E               Failed: Expected to perform 55 queries but 70 were done

I confirmed I see these failures too from saleor/graphql/checkout/tests

=========================================================================== short test summary info ============================================================================
FAILED saleor/graphql/checkout/tests/test_checkout_filters.py::test_checkout_query_with_filter_channels_with_one_channel - AssertionError: [{'message': 'More than one channe...
FAILED saleor/graphql/checkout/tests/test_checkout_filters.py::test_checkout_query_with_filter_channels_with_empty_channel - AssertionError: [{'message': 'More than one chan...
FAILED saleor/graphql/checkout/tests/test_checkout_filters.py::test_checkout_query_with_filter_channels_with_many_channel - AssertionError: [{'message': 'More than one chann...
FAILED saleor/graphql/checkout/tests/test_checkout_filters.py::test_checkout_query_with_filter_channels_without_channel - AssertionError: [{'message': 'More than one channel...
FAILED saleor/graphql/checkout/tests/benchmark/test_checkout_mutations.py::test_add_checkout_lines - AssertionError: [{'message': 'super(): __class__ cell not found', 'locat...
FAILED saleor/graphql/checkout/tests/benchmark/test_checkout_mutations.py::test_add_shipping_to_checkout - AssertionError: [{'message': 'super(): __class__ cell not found', ...
FAILED saleor/graphql/checkout/tests/benchmark/test_checkout_mutations.py::test_create_checkout_with_reservations - AssertionError: [{'message': 'super(): __class__ cell not...
FAILED saleor/graphql/checkout/tests/benchmark/test_checkout_mutations.py::test_add_delivery_to_checkout - AssertionError: [{'message': 'super(): __class__ cell not found', ...
FAILED saleor/graphql/checkout/tests/benchmark/test_checkout_mutations.py::test_complete_checkout_with_out_of_stock_webhook - AssertionError: [{'message': 'super(): __class_...
FAILED saleor/graphql/checkout/tests/benchmark/test_checkout_mutations.py::test_create_checkout - AssertionError: [{'message': 'super(): __class__ cell not found', 'location...
FAILED saleor/graphql/checkout/tests/benchmark/test_checkout_mutations.py::test_update_checkout_lines_with_reservations - AssertionError: [{'message': 'super(): __class__ ce...
FAILED saleor/graphql/checkout/tests/benchmark/test_checkout_mutations.py::test_add_billing_address_to_checkout - AssertionError: [{'message': 'super(): __class__ cell not f...
FAILED saleor/graphql/checkout/tests/benchmark/test_checkout_mutations.py::test_update_checkout_lines - AssertionError: [{'message': 'super(): __class__ cell not found', 'lo...
FAILED saleor/graphql/checkout/tests/benchmark/test_homepage.py::test_user_checkout_details_with_tax_app - AssertionError: [{'message': 'super(): __class__ cell not found', ...
FAILED saleor/graphql/checkout/tests/benchmark/test_checkout_mutations.py::test_checkout_payment_charge - AssertionError: [{'message': 'super(): __class__ cell not found', '...
FAILED saleor/graphql/checkout/tests/benchmark/test_checkout_mutations.py::test_add_checkout_lines_with_reservations - AssertionError: [{'message': 'super(): __class__ cell ...
FAILED saleor/graphql/checkout/tests/benchmark/test_checkout_mutations.py::test_add_checkout_lines_with_external_shipping - AssertionError: [{'message': 'super(): __class__ ...
FAILED saleor/graphql/checkout/tests/benchmark/test_checkout_mutations.py::test_checkout_shipping_address_update - AssertionError: [{'message': 'super(): __class__ cell not ...
FAILED saleor/graphql/checkout/tests/benchmark/test_checkout_mutations.py::test_complete_checkout - AssertionError: [{'message': 'super(): __class__ cell not found', 'locati...
FAILED saleor/graphql/checkout/tests/benchmark/test_checkout_mutations.py::test_customer_complete_checkout - AssertionError: [{'message': 'super(): __class__ cell not found'...
FAILED saleor/graphql/checkout/tests/benchmark/test_checkout_mutations.py::test_complete_checkout_with_single_line - AssertionError: [{'message': 'super(): __class__ cell no...
FAILED saleor/graphql/checkout/tests/benchmark/test_checkout_mutations.py::test_checkout_email_update - AssertionError: [{'message': 'super(): __class__ cell not found', 'lo...
FAILED saleor/graphql/checkout/tests/benchmark/test_checkout_mutations.py::test_checkout_voucher_code - AssertionError: [{'message': 'super(): __class__ cell not found', 'lo...
FAILED saleor/graphql/checkout/tests/benchmark/test_homepage.py::test_user_checkout_details - AssertionError: [{'message': 'super(): __class__ cell not found', 'locations': ...
FAILED saleor/graphql/checkout/tests/benchmark/test_checkout_mutations.py::test_complete_checkout_with_digital_line - AssertionError: [{'message': 'super(): __class__ cell n...
FAILED saleor/graphql/checkout/tests/benchmark/test_checkout_mutations.py::test_complete_checkout_preorder - AssertionError: [{'message': 'super(): __class__ cell not found'...
FAILED saleor/graphql/checkout/tests/benchmark/test_checkout_mutations.py::test_customer_complete_checkout_for_cc - AssertionError: [{'message': 'super(): __class__ cell not...
=========================================================== 27 failed, 563 passed, 31 warnings in 559.91s (0:09:19) ============================================================

[symwell]

With APPMAP=true checkout_line.variant.preorder_global_threshold is set to None instead of 7 after these lines

    variant = preorder_variant_channel_threshold
    variant.preorder_global_threshold = 7
    variant.save()

APPMAP=true py.test -s -v saleor/warehouse/tests/test_preorder_reservations_management.py

2022-10-17 10:39:09,632 WARNING saleor.warehouse.tests.test_preorder_reservations_management test_preorder_reservation_fails_if_global_threshold_was_allocated.2 has checkout_line.variant.preorder_global_threshold None [PID:5497:MainThread]

APPMAP=false py.test -s -v saleor/warehouse/tests/test_preorder_reservations_management.py

2022-10-17 10:36:06,921 WARNING saleor.warehouse.tests.test_preorder_reservations_management test_preorder_reservation_fails_if_global_threshold_was_allocated.2 has checkout_line.variant.preorder_global_threshold 7 [PID:5433:MainThread]

[symwell]

In another run:

Whatever happened between: 2022-10-17 10:52:43,685 and 2022-10-17 10:52:43,687 must be the bug

Basically these lines don't have the expected effect of variant.preorder_global_threshold being set to 7

    variant = preorder_variant_channel_threshold
    variant.preorder_global_threshold = 7
    variant.save()

2022-10-17 10:52:43,685 WARNING saleor.warehouse.tests.test_preorder_reservations_management test_preorder_reservation_fails_if_global_threshold_was_allocated.0 will set variant.preorder_global_threshold [PID:5633:MainThread]
2022-10-17 10:52:43,687 WARNING saleor.warehouse.tests.test_preorder_reservations_management test_preorder_reservation_fails_if_global_threshold_was_allocated.1 has variant.preorder_global_threshold 7 [PID:5633:MainThread]
2022-10-17 10:52:43,687 WARNING saleor.warehouse.tests.test_preorder_reservations_management test_preorder_reservation_fails_if_global_threshold_was_allocated.2 has checkout_line.variant.preorder_global_threshold None [PID:5633:MainThread]

The queries at that time are:

2022-10-17 15:52:43.684 UTC [4477] LOG:  statement: UPDATE "checkout_checkoutline" SET "private_metadata" = '{}', "metadata" = '{}', "old_id" = NULL, "created_at" = '2022-10-17T15:52:43.675281+00:00'::timestamptz, "checkout_id" = '4343507d-504c-469e-82af-93f4d7d61575'::uuid, "variant_id" = 3, "quantity" = 5, "price_override" = NULL, "currency" = 'USD', "total_price_net_amount" = 0.000, "total_price_gross_amount" = 0.000, "tax_rate" = 0.0000 WHERE "checkout_checkoutline"."id" = '4d2c1c8f-ee52-4573-94ec-21b6f11cc05e'::uuid
2022-10-17 15:52:43.686 UTC [4477] LOG:  statement: UPDATE "product_productvariant" SET "sort_order" = 2, "private_metadata" = '{}', "metadata" = '{}', "sku" = 'SKU_B_P', "name" = '', "product_id" = 1, "track_inventory" = true, "is_preorder" = true, "preorder_end_date" = NULL, "preorder_global_threshold" = 7, "quantity_limit_per_customer" = NULL, "created_at" = '2022-10-17T15:52:43.642136+00:00'::timestamptz, "updated_at" = '2022-10-17T15:52:43.685929+00:00'::timestamptz, "weight" = NULL WHERE "product_productvariant"."id" = 3
2022-10-17 15:52:43.687 UTC [4477] LOG:  statement: INSERT INTO "product_productvariantchannellisting" ("variant_id", "channel_id", "currency", "price_amount", "cost_price_amount", "preorder_quantity_threshold") VALUES (3, 2, 'PLN', 10, 1, 10) RETURNING "product_productvariantchannellisting"."id"

These at the top and bottom look unusual

2022-10-17 15:52:43.619 UTC [4477] LOG:  statement: SAVEPOINT "s140019978090304_x8"
2022-10-17 15:52:43.620 UTC [4477] LOG:  statement: INSERT INTO "attribute_assignedvariantattribute" ("variant_id", "assignment_id") VALUES (1, 1) RETURNING "attribute_assignedvariantattribute"."id"
2022-10-17 15:52:43.621 UTC [4477] LOG:  statement: RELEASE SAVEPOINT "s140019978090304_x8"

2022-10-17 15:52:43.986 UTC [4477] LOG:  statement: SELECT 1
2022-10-17 15:52:43.986 UTC [4477] LOG:  statement: SET CONSTRAINTS ALL IMMEDIATE
2022-10-17 15:52:43.992 UTC [4477] LOG:  statement: SET CONSTRAINTS ALL DEFERRED
2022-10-17 15:52:43.992 UTC [4477] LOG:  statement: ROLLBACK

Adding logging statements in try and finally in django.py:ExecuteWrapper:__call__ doesn't show a difference in the sql issued between APPMAP=false and APPMAP=true.

Adding logging statements in sqlalchemy.py capture_sql_call and capture_sql shows they're not being used.

Saleor's approach of running on_commit hooks seems unusual.

[symwell]

In summary, the correct SQL does get issued in response to these lines from test_preorder_reservations_management.py:test_preorder_reservation_fails_if_global_threshold_was_allocated

    variant = preorder_variant_channel_threshold
    variant.preorder_global_threshold = 7
    variant.save()

The SQL is

UPDATE "checkout_checkoutline"
   SET "private_metadata" = '{}',
       "metadata" = '{}',
       "old_id" = NULL,
       "created_at" = '2022-10-17T19:55:18.172088+00:00'::timestamptz,
       "checkout_id" = '55a36927-1934-4531-b2a9-17b066944eec'::uuid,
       "variant_id" = 3,
       "quantity" = 5,
       "price_override" = NULL,
       "currency" = 'USD',
       "total_price_net_amount" = 0.000,
       "total_price_gross_amount" = 0.000,
       "tax_rate" = 0.0000
WHERE "checkout_checkoutline"."id" = '56a9ed41-07bf-4298-88cd-450819a625e6'::uuid;

UPDATE "product_productvariant"
   SET "sort_order" = 2,
       "private_metadata" = '{}',
       "metadata" = '{}',
       "sku" = 'SKU_B_P',
       "name" = '',
       "product_id" = 1,
       "track_inventory" = true,
       "is_preorder" = true,
       "preorder_end_date" = NULL,
       "preorder_global_threshold" = 7,
       "quantity_limit_per_customer" = NULL,
       "created_at" = '2022-10-17T19:55:18.147799+00:00'::timestamptz,
       "updated_at" = '2022-10-17T19:55:18.186634+00:00'::timestamptz,
       "weight" = NULL
WHERE "product_productvariant"."id" = 3

This SQL intends to set checkout_line.variant to be product_productvariant with id 3. This would lead to checkout_line.variant.preorder_global_threshold to be 7.

But this update doesn't get applied. No exception is raised.

Or if the update does get applied the corresponding value isn't in memory in Python.

The table definition of product_productvariant reports:

\d product_productvariant

    TABLE "checkout_checkoutline" CONSTRAINT "cart_cartline_variant_id_dbca56c9_fk_product_productvariant_id" FOREIGN KEY (variant_id) REFERENCES product_productvariant(id) DEFERRABLE INITIALLY DEFERRED

This definition means it's ok to insert values that don't initially meet the referential integrity constraint as long as they do meet the constraint by the time the transaction ends. Somehow the update doesn't get applied.

[symwell]

The test passed with

APPMAP_DISPLAY_PARAMS=false APPMAP=true py.test -s -v saleor/warehouse/tests/test_preorder_reservations_management.py

[symwell]

These fail

[gw2] FAILED saleor/graphql/app/tests/benchmarks/test_app_extensions.py::test_app_extensions_with_filter[filter2]
[gw3] FAILED saleor/graphql/account/tests/test_account_permission_group.py::test_permission_groups_query[permission_group_filter1-2]
[gw1] FAILED saleor/graphql/app/tests/benchmarks/test_app_extensions.py::test_app_extensions_with_filter[filter3]
[gw3] FAILED saleor/graphql/account/tests/test_pagination.py::test_query_customer_members_pagination_with_filter_search[customer_filter3-users_order3]

with the error message

Traceback (most recent call last):
  File "/app/saleor/channel/utils.py", line 27, in get_default_channel
    channel = Channel.objects.get()
  File "/usr/local/lib/python3.9/site-packages/django/db/models/manager.py", line 85, in manager_method
    return getattr(self.get_queryset(), name)(*args, **kwargs)
  File "/usr/local/lib/python3.9/site-packages/django/db/models/query.py", line 435, in get
    raise self.model.DoesNotExist(
saleor.channel.models.Channel.DoesNotExist: Channel matching query does not exist.

The error means a query was issued to find a Channel object in the database but one did not exist.

[symwell]

fwiw with the recent release of appmap-python tests that used to fail now pass. I'll run the full saleor testsuite again now.

No they don't. I hadn't set APPMAP=true.

[symwell]

Saleor contains 284K lines of code. Must "the bug" be identified and fixed specifically in Saleor? Is there no other free Python project with fewer lines of code that demonstrates this bug?

[apotterri]

Well, given that the bug is in the python agent, not in saleor, I'm not sure why the size of saleor is relevant. This also means that the fix wouldn't be specific to saleor.

[symwell]

Smaller code indicates higher code quality, including higher testcase quality. I was expecting running the bad testcase would generate only a small number of queries but instead a lot of other things get executed before and after. It's hard to isolate the effects of a single testcase.

[symwell]

1) Channels

The saleor database contains rows for Channel.

saleor=# select * from channel_channel;
 id |      name       |      slug       | is_active | currency_code | default_country 
----+-----------------+-----------------+-----------+---------------+-----------------
  1 | Default Channel | default-channel | t         | USD           | US
  2 | Channel-PLN     | channel-pln     | t         | PLN           | PL
(2 rows)

With either APPMAP=true or APPMAP=false the cloned databases don't contain rows for Channel.

test_saleor_gw0=# \c test_saleor_gw4
You are now connected to database "test_saleor_gw4" as user "saleor".
test_saleor_gw4=# select * from channel_channel;
 id | name | slug | is_active | currency_code | default_country 
----+------+------+-----------+---------------+-----------------
(0 rows)

test_saleor_gw4=# \c test_saleor_gw3
FATAL:  database "test_saleor_gw3" does not exist
Previous connection kept
test_saleor_gw4=# select * from channel_channel;
 id | name | slug | is_active | currency_code | default_country 
----+------+------+-----------+---------------+-----------------
(0 rows)

test_saleor_gw4=# \c test_saleor_gw2
You are now connected to database "test_saleor_gw2" as user "saleor".
test_saleor_gw2=# select * from channel_channel;
 id | name | slug | is_active | currency_code | default_country 
----+------+------+-----------+---------------+-----------------
(0 rows)

test_saleor_gw2=# \c test_saleor_gw1
You are now connected to database "test_saleor_gw1" as user "saleor".
test_saleor_gw1=# select * from channel_channel;
 id | name | slug | is_active | currency_code | default_country 
----+------+------+-----------+---------------+-----------------
(0 rows

I searched the logs for "channel_channel" over the date range of the last test, and don't see an INSERT INTO "channel_channel". Also don't see a DELETE FROM "channel_channel".

I do see the following before that testcase, over a different date range and unsure on which db:

2022-10-27 12:44:28.597 UTC [2944] LOG:  statement: INSERT INTO "channel_channel" ("name", "is_active", "slug", "currency_code", "default_country") VALUES ('Main Channel', true, 'main', 'USD', 'US') RETURNING "channel_channel"."id"

The last test is

APPMAP_DISPLAY_PARAMS=false APPMAP=false pytest -s -v saleor/graphql/app/tests/benchmarks/test_app_extensions.py

This looks strange. The test passed, finding a Channel object, when no Channel objects were in the db, no Channel objects were inserted and no Channel objects were deleted.

Maybe it copied data in some other way from the base saleor db? The logs don't show a COPY statement.

Maybe it didn't need to use channels?

0004_initial.py:create_default_channel doesn't create a channel when APPMAP=false.

2) Django

Commented out the sql recording logic of Appmap's Django support. Now it basically says finally: pass. It failed. So the bug isn't the sql recording logic.

Commented out the execution wrapper installation logic. It failed.

Changed Middleware's __call__ to always return self.get_response(request) so it doesn't record. It failed.

So the bug isn't in wrapping Django.

3) instrument_functions

Changed the logic in instrument_functions to instrument only functions that contain a specific letter in them.

            functions_new = []
            for fn_name, static_fn, fn in functions:
                if "p" in fn_name:
                    functions_new.append((fn_name, static_fn, fn))
            functions = functions_new
            if functions and len(functions) > 0:
                out = ""
                for fn_name, static_fn, fn in functions:
                    out += fn_name + " "
                logger.warning("  instrumented_functions     %s", out)

This lead to the testcase passing. Will try to find a small group of functions or single function that causes the testcase failure.

A function containing the letter p in it breaks. The tr statement splits a line with multiple words into multiple lines, one per word.

cat instrumented_functions_breaks_p.txt  | grep 'instrumented_functions' | grep -v :MainThread | sed -e 's/.*instrumented_functions//g' | tr -s '[:blank:]' '\n' | sort | uniq | wc -l
1536

[symwell]

When only the function get_default_channel_slug_or_graphql_error is instrumented and nothing else is instrumented, the following Saleor testcase fails.

APPMAP_DISPLAY_PARAMS=false APPMAP=true pytest -s -v saleor/graphql/app/tests/benchmarks/test_app_extensions.py

The bug has to be related to instrumenting this function.

I'll try to reproduce this in a standalone testcase.

[dividedmind]

When only the function get_default_channel_slug_or_graphql_error is instrumented and nothing else is instrumented, the following Saleor testcase fails.

APPMAP_DISPLAY_PARAMS=false APPMAP=true pytest -s -v saleor/graphql/app/tests/benchmarks/test_app_extensions.py

The bug has to be related to instrumenting this function.

I'll try to reproduce this in a standalone testcase.

Thanks! #188 should fix this problem. I'm currently running the test suite with the fix to see if there's anything else.

[symwell]

With the fix from https://github.com/getappmap/appmap-python/pull/188 these tests that used to fail now pass:

These fail

[gw2] FAILED saleor/graphql/app/tests/benchmarks/test_app_extensions.py::test_app_extensions_with_filter[filter2]
[gw3] FAILED saleor/graphql/account/tests/test_account_permission_group.py::test_permission_groups_query[permission_group_filter1-2]
[gw1] FAILED saleor/graphql/app/tests/benchmarks/test_app_extensions.py::test_app_extensions_with_filter[filter3]
[gw3] FAILED saleor/graphql/account/tests/test_pagination.py::test_query_customer_members_pagination_with_filter_search[customer_filter3-users_order3]

These tests currently fail

=========================================================================== short test summary info ============================================================================
FAILED saleor/graphql/product/tests/test_product_type_update.py::test_update_product_type_kind_omitted - AssertionError: [{'message': 'Signature has expired', 'locations': [...
FAILED saleor/graphql/product/tests/test_category.py::test_create_category_with_given_slug[None-test-category] - AssertionError: [{'message': 'Signature has expired', 'locat...
FAILED saleor/graphql/product/tests/test_product.py::test_reorder_media_some_media_marked_as_to_remove - AssertionError: [{'message': 'Signature has expired', 'locations': [...
FAILED saleor/graphql/product/tests/benchmark/test_product_variant_channel_listing_update.py::test_variant_channel_listing_update - AssertionError: [{'message': 'Signature h...
FAILED saleor/graphql/order/tests/deprecated/test_order.py::test_order_line_remove_by_old_line_id[draft] - AssertionError: [{'message': 'Signature has expired', 'locations':...
FAILED saleor/graphql/translations/tests/test_translations.py::test_translation_query_voucher[perm_codenames0-False] - TypeError: 'NoneType' object is not subscriptable
FAILED saleor/graphql/product/tests/test_variant.py::test_fetch_unpublished_variant_staff_user - AssertionError: [{'message': 'Signature has expired', 'locations': [{'line':...
====================================================== 7 failed, 8042 passed, 1 skipped, 9 warnings in 3432.19s (0:57:12) ======================================================

[symwell]

All salor tests pass after the fix.

The tests that didn't pass when I ran all tests together do pass when run individually.

# these tests pass when I run them standalone
APPMAP_DISPLAY_PARAMS=false APPMAP=true pytest -s -v saleor/graphql/product/tests/test_product_type_update.py
APPMAP_DISPLAY_PARAMS=false APPMAP=true pytest -s -v saleor/graphql/product/tests/test_category.py
APPMAP_DISPLAY_PARAMS=false APPMAP=true pytest -s -v saleor/graphql/product/tests/test_product.py
APPMAP_DISPLAY_PARAMS=false APPMAP=true pytest -s -v saleor/graphql/product/tests/benchmark/test_product_variant_channel_listing_update.py
APPMAP_DISPLAY_PARAMS=false APPMAP=true pytest -s -v saleor/graphql/order/tests/deprecated/test_order.py; 
APPMAP_DISPLAY_PARAMS=false APPMAP=true pytest -s -v saleor/graphql/translations/tests/test_translations.py
APPMAP_DISPLAY_PARAMS=false APPMAP=true pytest -s -v saleor/graphql/product/tests/test_variant.py

6 out of 7 of the previous test failures were with a "Signature has expired" error. The load on my machine was high running the tests. Maybe the failures were due to the high load.

I extracted saleor from commit 22fa83ecf3b20bec472c71fef0b4216e87bdbaa9 (Aug 26 2022) because the latest version couldn't start the docker containers for me.