__debug, __sql doesn't log sql queries made withing promises or resolves In Types

[japrogramer]

Hello world, I have a query that has promises with data loaders, In those dataloaders I do queries that don't show up in
the queries

__debug{ __sql{ sql}}

[japrogramer]

for example I only see three queries here, but In reality Im making queries to resolve products, but it doesn't show up.

{
  __debug {
    sql {
      sql
    }
  }
  wish(pk: "2") {
    products {
      pageInfo {
        startCursor
        endCursor
      }
      edges {
        through {
          reason
        }
        node {
          title
          description
        }
      }
    }
  }
}

{
  "data": {
    "__debug": {
      "sql": [
        {
          "sql": "SELECT \"django_session\".\"session_key\", \"django_session\".\"session_data\", \"django_session\".\"expire_date\" FROM \"django_session\" WHERE (\"django_session\".\"session_key\" = 'xehibq5ogjxdrumveit2sffayy3ehly0' AND \"django_session\".\"expire_date\" > '2017-10-17T20:15:20.569297+00:00'::timestamptz)"
        },
        {
          "sql": "SELECT \"users_user\".\"id\", \"users_user\".\"password\", \"users_user\".\"last_login\", \"users_user\".\"is_superuser\", \"users_user\".\"username\", \"users_user\".\"first_name\", \"users_user\".\"last_name\", \"users_user\".\"email\", \"users_user\".\"is_staff\", \"users_user\".\"is_active\", \"users_user\".\"date_joined\", \"users_user\".\"name\", \"users_user\".\"uuid\" FROM \"users_user\" WHERE \"users_user\".\"id\" = 1"
        },
        {
          "sql": "SELECT \"wishlist_wish\".\"id\", \"wishlist_wish\".\"private\", \"wishlist_wish\".\"created\", \"wishlist_wish\".\"updated\", \"wishlist_wish\".\"title\", \"wishlist_wish\".\"owner_id\", \"wishlist_wish\".\"description\" FROM \"wishlist_wish\" WHERE \"wishlist_wish\".\"id\" = 2"
        }
      ]
    },
    "wish": {
      "products": {
        "pageInfo": {
          "startCursor": "YXJyYXljb25uZWN0aW9uOjA=",
          "endCursor": "YXJyYXljb25uZWN0aW9uOjE="
        },
        "edges": [
          {
            "through": {
              "reason": "To make things make sense"
            },
            "node": {
              "title": "needs more data",
              "description": "Needs more Rhyme more Reason"
            }
          },
          {
            "through": {
              "reason": "testing"
            },
            "node": {
              "title": "p1",
              "description": "test"
            }
          }
        ]
      }
    }
  }
}

and this is the query that isn't being showed, This query happens in a Type

    def resolve_products(self, info):                                    
        qs = Reason.objects.filter(wish=self).only('reason')             
        return self.products.prefetch_related(                           
            Prefetch('reason_set', queryset=qs, to_attr='preason')).all()        

[japrogramer]

it seems that because the promise resolves after the schema.execute returns there is no way for the __debug middleware from graphene to know which sql actually executed.

[rafaponieman]

I may be wrong, but it seems to me it's affecting every case where I query through reverse Foreign Key relation. For example, with the following query:

query {
  products {
    name
    variants {
      id
      code
    }
  }
}

And the Schema query:

class Query(graphene.ObjectType):
    products = graphene.List(ProductType)

And Product Django Object Type

class VariantType(DjangoObjectType):

    class Meta:
        model = Variant

class ProductType(DjangoObjectType):
    variants = graphene.List(Variant)

    def resolve_variants(self, info):
        return self.variants.filter(active=True)

    class Meta:
        model = Product

I'll see a query for Products reported, but none for Variants (although it is happening).

[japrogramer]

Yes I think that the sql tag should be resolved after the rest of the query is resolved .. even after promises are resolved in the query. That would resolve a lot of issues.

[tricoder42]

I've just hit the same issue. It was suspicious that I don't see N+1 queries when I skipped select_related...

As a workaround, I'm auditing sql in tests using snapshots. I use this wrapper around snapshottest:

id_re = re.compile(r'(_?id["\']) = \d+')
in_re = re.compile(r"IN \(\d+(\s?, \d+)*\)")
# project specific substitution
key_re = re.compile(r'(_?key["\']) = \'\w+\'')


@pytest.fixture
def assert_sql_snapshot(snapshot):
    """
    Create/compare a snapshot of sql queries which were executed inside this context.
    IDs are replaced with `ID` placehodler to assure independence on db sequences.
    """

    @contextmanager
    def _assert():
        with CaptureQueriesContext(connection) as context:
            yield
            queries = ";".join(query["sql"] for query in context)
            queries = id_re.sub(r"\1 = ID", queries)
            queries = in_re.sub(r"IN (IDs)", queries)
            queries = key_re.sub(r"\1 = KEY", queries)
            sql = sqlparse.format(queries, reindent=True, keyword_case="upper")
            snapshot.assert_match(sql)

    return _assert

Then I wrap the client.execute inside:

    def test_query(self, client, assert_sql_snapshot):
        with assert_sql_snapshot():
            executed = client.execute(...)
        # other asserts

When the snapshot is generated, I check that there're no extra queries. It's also useful to check if the query could be further optimized.

[ktosiek]

Looking at the code of that middleware, I see it waits for all promises that where seen by the middleware before starting to resolve __sql.
I think something like this might work:

class DjangoDebugContext(object):
    (...)
    def get_debug_promise(self):
        if not self.debug_promise:
            self.debug_promise = Promise.all(self.promises)
            self.promises = []
        return self.debug_promise.then(self.on_resolve_all_promises)

    def on_resolve_all_promises(self, values):
        if self.promises:
            self.debug_promise = None
            return self.get_debug_promise()
        self.disable_instrumentation()
        return self.object

    def add_promise(self, promise):
        if self.debug_promise:
            self.promises.append(promise)

Edit: it works, I've made a PR out of it: #591.

[dopeboy]

Closing this down as I see we have a PR out of it (thanks @ktosiek!).