unify logging for writing datastore entities into post put hook

and other logging tweaks

activitypub.py

@@ -118,7 +118,7 @@ def inbox(domain=None):
         seen_ids[id] = True
         if already_seen or Object.get_by_id(id):
             msg = f'Already handled this activity {id}'
-            logging.info(msg)
+            logger.info(msg)
             return msg, 200
 
     activity_as1 = as2.to_as1(activity)
@@ -151,7 +151,6 @@ def inbox(domain=None):
         if not obj_id:
             error("Couldn't find obj_id of object to update")
 
-        logger.info(f'updating Object {obj_id}')
         obj = Object.get_by_id(obj_id) or Object(id=obj_id)
         obj.populate(
             as2=json_dumps(obj_as2),
@@ -212,13 +211,13 @@ def inbox(domain=None):
         # not Like, Follow, or other activity types, since Mastodon doesn't
         # currently mark those as explicitly public.
         if not as2.is_public(activity_unwrapped):
-            logging.info('Dropping non-public activity')
+            logger.info('Dropping non-public activity')
             return ''
 
         if actor:
             actor_id = actor.get('id')
             if actor_id:
-                logging.info(f'Finding followers of {actor_id}')
+                logger.info(f'Finding followers of {actor_id}')
                 activity_obj.domains = [
                     f.src for f in Follower.query(Follower.dest == actor_id,
                                                   projection=[Follower.src]).fetch()]
@@ -227,7 +226,6 @@ def inbox(domain=None):
         activity_obj.as1 = activity_as1_str
         activity_obj.labels = ['feed', 'activity']
         activity_obj.put()
-        logging.info(f'Wrote Object {id} for {len(activity_obj.domains)} followers')
 
     return 'OK'
 
@@ -314,7 +312,6 @@ def undo_follow(undo_unwrapped):
     user_domain = util.domain_from_link(followee, minimize=False)
     follower_obj = Follower.get_by_id(Follower._id(dest=user_domain, src=follower))
     if follower_obj:
-        logger.info(f'Marking {follower_obj.key} as inactive')
         follower_obj.status = 'inactive'
         follower_obj.put()
     else:

common.py

@@ -134,12 +134,12 @@ def get_object(id, user=None):
     obj = Object.get_by_id(id)
     if obj:
       if obj.as2:
-        logging.info(f'Got Object from datastore: {id}')
+        logger.info(f'Got Object from datastore: {id}')
         return obj
     else:
       obj = Object(id=id)
 
-    logging.info(f'Object not in datastore or has no as2: {id}')
+    logger.info(f'Object not in datastore or has no as2: {id}')
     obj_as2 = get_as2(id, user=user).json()
     obj.populate(as2=json_dumps(obj_as2),
                  as1=json_dumps(as2.to_as1(obj_as2)),
@@ -179,7 +179,7 @@ def signed_request(fn, url, user, data=None, log_data=True, headers=None, **kwar
 
     if data:
         if log_data:
-            logging.info(f'Sending AS2 object: {json_dumps(data, indent=2)}')
+            logger.info(f'Sending AS2 object: {json_dumps(data, indent=2)}')
         data = json_dumps(data).encode()
 
     headers = copy.deepcopy(headers)
@@ -359,7 +359,6 @@ def send_webmentions(activity_wrapped, proxy=None, **object_props):
     if activity.get('objectType') == 'activity':
       obj.labels.append('activity')
     obj.put()
-    logging.info(f'Created Object {source}')
 
     while obj.undelivered:
         target = obj.undelivered.pop()
@@ -394,7 +393,6 @@ def send_webmentions(activity_wrapped, proxy=None, **object_props):
 
     obj.status = 'complete' if obj.delivered else 'failed' if obj.failed else 'ignored'
     obj.put()
-    logging.info(f'Finalized Object {source} as {obj.status}')
 
     if errors:
         msg = 'Errors: ' + ', '.join(f'{code} {body}' for code, body in errors)

follow.py

@@ -173,7 +173,6 @@ class FollowCallback(indieauth.Callback):
                source_protocol='ui', status='complete', as2=follow_json,
                as1=json_dumps(as2.to_as1(follow_as2), sort_keys=True),
                ).put()
-        logging.info(f'Wrote Object {follow_id}')
 
         link = common.pretty_link(util.get_url(followee) or id, text=addr)
         flash(f'Followed {link}.')
@@ -243,7 +242,6 @@ class UnfollowCallback(indieauth.Callback):
                as2=json_dumps(unfollow_as2, sort_keys=True),
                as1=json_dumps(as2.to_as1(unfollow_as2), sort_keys=True),
                ).put()
-        logging.info(f'Wrote Object {unfollow_id}')
 
         link = common.pretty_link(util.get_url(followee) or followee_id)
         flash(f'Unfollowed {link}.')

models.py

@@ -78,6 +78,9 @@ class User(StringIdModel):
     def _get_kind(cls):
         return 'MagicKey'
 
+    def _post_put_hook(self, future):
+        logger.info(f'Wrote User {self.key.id()}')
+
     @classmethod
     def get_by_id(cls, id):
         """Override Model.get_by_id to follow the use_instead property."""
@@ -199,7 +202,7 @@ class User(StringIdModel):
             try:
                 resp = util.requests_get(root_site, gateway=False)
                 if resp.ok and self.is_homepage(resp.url):
-                    logging.info(f'{root_site} redirects to {resp.url} ; using {root} instead')
+                    logger.info(f'{root_site} redirects to {resp.url} ; using {root} instead')
                     root_user = User.get_or_create(root)
                     self.use_instead = root_user.key
                     self.put()
@@ -305,6 +308,7 @@ class Object(StringIdModel):
     def _post_put_hook(self, future):
         """Update :func:`common.get_object` cache."""
         # TODO: assert that as1 id is same as key id? in pre put hook?
+        logger.info(f'Wrote Object {self.key.id()} {self.type} {self.status or ""} {self.labels} for {len(self.domains)} users')
         if self.type != 'activity':
             key = common.get_object.cache_key(self.key.id())
             common.get_object.cache[key] = self
@@ -365,6 +369,9 @@ class Follower(StringIdModel):
     created = ndb.DateTimeProperty(auto_now_add=True)
     updated = ndb.DateTimeProperty(auto_now=True)
 
+    def _post_put_hook(self, future):
+        logger.info(f'Wrote Follower {self.key.id()} {self.status}')
+
     @classmethod
     def _id(cls, dest, src):
         assert src
@@ -373,7 +380,6 @@ class Follower(StringIdModel):
 
     @classmethod
     def get_or_create(cls, dest, src, **kwargs):
-        logger.info(f'new Follower from {src} to {dest}')
         follower = cls.get_or_insert(cls._id(dest, src), src=src, dest=dest, **kwargs)
         follower.dest = dest
         follower.src = src

webmention.py

@@ -143,12 +143,12 @@ class Webmention(View):
         changed = False
 
         if obj:
-            logging.info(f'Resuming existing {obj}')
+            logger.info(f'Resuming existing {obj}')
             obj.failed = []
             seen = [t.uri for t in obj.delivered + obj.undelivered + obj.failed]
             new_inboxes = [i for i in inboxes_to_targets.keys() if i not in seen]
             if new_inboxes:
-                logging.info(f'Adding new inboxes: {new_inboxes}')
+                logger.info(f'Adding new inboxes: {new_inboxes}')
                 obj.undelivered += [Target(uri=uri, protocol='activitypub')
                                     for uri in new_inboxes]
             if type in ('note', 'article', 'comment'):
@@ -163,7 +163,6 @@ class Webmention(View):
                          undelivered=[Target(uri=uri, protocol='activitypub')
                                       for uri in inboxes_to_targets.keys()],
                          status='in progress')
-            logging.info(f'Storing new Object {self.source_url}')
 
         obj.domains = [self.source_domain]
         obj.source_protocol = 'webmention'
@@ -183,7 +182,7 @@ class Webmention(View):
             if inbox in inboxes_to_targets:
                 target_as2 = inboxes_to_targets[inbox]
             else:
-                logging.warning(f'Missing target_as2 for inbox {inbox}!')
+                logger.warning(f'Missing target_as2 for inbox {inbox}!')
                 target_as2 = None
 
             if not self.source_as2:
@@ -330,7 +329,7 @@ class Webmention(View):
 
             if not inbox_url:
                 # TODO: probably need a way to surface errors like this
-                logging.error('Target actor has no inbox')
+                logger.error('Target actor has no inbox')
                 continue
 
             inbox_url = urllib.parse.urljoin(target, inbox_url)