temporarily turn on ndb logging for cache and lookups

for #1149

app.yaml

@@ -36,7 +36,7 @@ env_variables:
   # ...or test against labeler.dholms.xyz / did:plc:vzxheqfwpbi3lxbgdh22js66
 
   # https://github.com/googleapis/python-ndb/blob/c55ec62b5153787404488b046c4bf6ffa02fee64/google/cloud/ndb/utils.py#L78-L81
-  # NDB_DEBUG: true
+  NDB_DEBUG: true
 
 handlers:
 

atproto_hub.yaml

@@ -36,7 +36,7 @@ env_variables:
   SUBSCRIBE_REPOS_BATCH_DELAY: 10
 
   # https://github.com/googleapis/python-ndb/blob/c55ec62b5153787404488b046c4bf6ffa02fee64/google/cloud/ndb/utils.py#L78-L81
-  # NDB_DEBUG: true
+  NDB_DEBUG: true
 
 # need only one instance so that new commits can be delivered to subscribeRepos
 # subscribers in memory

config.py

@@ -4,6 +4,8 @@
 """
 import logging
 import os
+import re
+import traceback
 
 from oauth_dropins.webutil import appengine_config, appengine_info, util
 
@@ -19,6 +21,8 @@
 # https://github.com/snarfed/bridgy-fed/issues/1593
 MAX_FORM_MEMORY_SIZE = 10000000
 
+config_logger = logging.getLogger(__name__)
+
 if appengine_info.DEBUG:
     ENV = 'development'
     CACHE_TYPE = 'NullCache'
@@ -39,7 +43,35 @@
 # for debugging ndb. also needs NDB_DEBUG env var.
 # https://github.com/googleapis/python-ndb/blob/c55ec62b5153787404488b046c4bf6ffa02fee64/google/cloud/ndb/utils.py#L78-L81
 # logging.getLogger('google.cloud.ndb').setLevel(logging.DEBUG)
-# logging.getLogger('google.cloud.ndb._cache').setLevel(logging.DEBUG)
+logging.getLogger('google.cloud.ndb._cache').setLevel(logging.DEBUG)
+
+KEYS_ID_RE = re.compile(f'name: "([^"]+)"')
+
+def only_lookups(record):
+    msg = record.getMessage()
+    if '\nkeys {' in msg:
+        if id := KEYS_ID_RE.search(msg):
+            stack = [frame for frame in traceback.extract_stack()[:-1]
+                     if frame.filename.startswith('/workspace/')
+                        or (frame.filename.startswith('/Users/ryan/src/')
+                            and '/lib/' not in frame.filename)]
+            new_msg = id.group(1) + '\n' + ''.join(traceback.format_list(stack))
+            config_logger.info(new_msg)
+
+            # ideally I'd return a new log record here and let the
+            # _datastore_api logger emit it, or just modify the record passed in
+            # here and return True, but that makes tests try to talk to google
+            # cloud's production logging (?)
+            #
+            # return logging.LogRecord(record.name, record.level, record.pathname,
+            #                       record.lineno, new_msg, record.args,
+            #                       record.exc_info))
+
+    return False
+
+api_logger = logging.getLogger('google.cloud.ndb._datastore_api')
+api_logger.setLevel(logging.DEBUG)
+api_logger.addFilter(only_lookups)
 
 os.environ.setdefault('APPVIEW_HOST', 'api.bsky.local')
 os.environ.setdefault('BGS_HOST', 'bgs.bsky.local')

router.yaml

@@ -28,7 +28,7 @@ env_variables:
   MEMCACHE_HOST: '10.126.144.3'
 
   # https://github.com/googleapis/python-ndb/blob/c55ec62b5153787404488b046c4bf6ffa02fee64/google/cloud/ndb/utils.py#L78-L81
-  # NDB_DEBUG: true
+  NDB_DEBUG: true
 
 automatic_scaling:
   min_num_instances: 2