Send smaller log lines (#1575)

* progress

* progress

api/channels_api.py

@@ -60,7 +60,8 @@ def fetch_chrome_release_info(version):
     result = requests.get(url, timeout=60)
     if result.status_code == 200:
       try:
-        logging.info('result.content is:\n%s', result.content)
+        logging.info(
+            'result.content is:\n%s', result.content[:settings.MAX_LOG_LINE])
         result_json = json.loads(result.content)
         if 'mstones' in result_json:
           data = result_json['mstones'][0]

api/metricsdata.py

@@ -1,6 +1,3 @@
-
-
-
 # -*- coding: utf-8 -*-
 # Copyright 2013 Google Inc.
 #
@@ -22,12 +19,11 @@ import datetime
 import json
 import logging
 
-# from google.appengine.api import users
 from framework import users
-
 from framework import basehandlers
 from internals import models
 from framework import ramcache
+import settings
 
 CACHE_AGE = 86400 # 24hrs
 
@@ -190,13 +186,15 @@ class FeatureHandler(basehandlers.FlaskHandler):
     else:
       properties = ramcache.get(self.CACHE_KEY)
       logging.info(
-          'looked at cache %r and found %r', self.CACHE_KEY, properties)
+          'looked at cache %r and found %s', self.CACHE_KEY,
+          repr(properties)[:settings.MAX_LOG_LINE])
       if properties is None:
         logging.info('Loading properties from datastore')
         properties = self.__query_metrics_for_properties()
         ramcache.set(self.CACHE_KEY, properties, time=CACHE_AGE)
 
-    logging.info('before filtering: %r', properties)
+    logging.info('before filtering: %s',
+                 repr(properties)[:settings.MAX_LOG_LINE])
     return _filter_metric_data(properties)
 
 

framework/basehandlers.py

@@ -155,7 +155,9 @@ class APIHandler(BaseHandler):
   def post(self, *args, **kwargs):
     """Handle an incoming HTTP POST request."""
     json_body = self.request.get_json(force=True, silent=True) or {}
-    logging.info('POST data is %r', json_body)
+    logging.info('POST data is:')
+    for k, v in json_body.items():
+      logging.info('%r: %s', k, repr(v)[:settings.MAX_LOG_LINE])
     is_login_request = str(self.request.url_rule) == '/api/v0/login'
 
     if not is_login_request:

framework/cloud_tasks_helpers.py

@@ -1,6 +1,3 @@
-
-
-
 # -*- coding: utf-8 -*-
 # Copyright 2020 Google Inc.
 #
@@ -63,7 +60,8 @@ class LocalCloudTasksClient(object):
         # This header can only be set on internal requests, not by users.
         headers={'X-AppEngine-QueueName': 'default'})
     logging.info('Task handler status: %d', handler_response.status_code)
-    logging.info('Task handler text: %r', handler_response.content)
+    logging.info('Task handler text: %r',
+                 handler_response.content[:settings.MAX_LOG_LINE])
 
 
 def _get_client():

framework/csp.py

@@ -13,9 +13,6 @@
 # See the License for the specific language governing permissions and
 # limitations under the License.
 
-
-
-
 import base64
 import copy
 import logging
@@ -24,6 +21,8 @@ import six
 
 import flask
 
+import settings
+
 
 REPORT_ONLY = False
 USE_NONCE_ONLY_POLICY = True  # Recommended
@@ -118,5 +117,6 @@ def get_headers(nonce):
 
 def report_handler():
   """Log any CSP violations that are reported to our app."""
-  logging.error('CSP Violation: %r' % flask.request.data)
+  logging.error('CSP Violation: %s' %
+                repr(flask.request.data)[:settings.MAX_LOG_LINE])
   return ''

framework/utils.py

@@ -13,9 +13,6 @@
 # See the License for the specific language governing permissions and
 # limitations under the License.
 
-
-
-
 import calendar
 import datetime
 import flask
@@ -23,9 +20,7 @@ import logging
 import time
 import traceback
 
-# from google.appengine.api import users
 from framework import users
-
 import settings
 
 from django.utils import feedgenerator
@@ -74,7 +69,7 @@ def retry(tries, delay=1, backoff=2):
             raise
           trace_str = traceback.format_exc()
           logging.warning('Retrying %s due to Exception: %s',
-                          func.__name__, trace_str)
+                          func.__name__, trace_str[:settings.MAX_LOG_LINE])
           time.sleep(_delay)
           _delay *= backoff  # Wait longer the next time we fail.
     return wrapper

internals/approval_defs.py

@@ -20,6 +20,7 @@ import requests
 
 from framework import permissions
 from framework import ramcache
+import settings
 
 CACHE_EXPIRATION = 60 * 60  # One hour
 
@@ -70,12 +71,12 @@ def fetch_owners(url):
   response = requests.get(url)
   if response.status_code != 200:
     logging.error('Could not fetch %r', url)
-    logging.error('Got response %r', response)
+    logging.error('Got response %s', repr(response)[:settings.MAX_LOG_LINE])
     raise ValueError('Could not get OWNERS file')
 
   decoded = base64.b64decode(response.content).decode()
   for line in decoded.split('\n'):
-    logging.info('got line: '  + line)
+    logging.info('got line: '  + line[:settings.MAX_LOG_LINE])
     if '#' in line:
       line = line[:line.index('#')]
     line = line.strip()

internals/detect_intent.py

@@ -104,7 +104,7 @@ class IntentEmailHandler(basehandlers.FlaskHandler):
                  'Subject:     %r\n'
                  'In reply to: %r\n'
                  'Body:        %r\n',
-                 from_addr, subject, in_reply_to, body)
+                 from_addr, subject, in_reply_to, body[:settings.MAX_LOG_LINE])
 
     approval_field = detect_field(subject)
     if not approval_field:

internals/fetchmetrics.py

@@ -13,9 +13,6 @@
 # See the License for the specific language governing permissions and
 # limitations under the License.
 
-
-
-
 import base64
 import datetime
 import json
@@ -97,8 +94,8 @@ class UmaQuery(object):
     j = json.loads(json_content)
     if 'r' not in j:
       logging.info(
-          '%s results do not have an "r" key in the response: %r' %
-          (self.query_name, j))
+          '%s results do not have an "r" key in the response: %s' %
+          (self.query_name, repr(j)[:settings.MAX_LOG_LINE]))
       logging.info('Note: uma-export can take 2 days to produce metrics')
       return (None, 404)
     return (j['r'], result.status_code)

internals/models.py

@@ -579,7 +579,8 @@ class Feature(DictModel):
   # TODO(jrobbins): Eliminate format version 1.
   def format_for_template(self, version=2):
     self.migrate_views()
-    logging.info('In format_for_template for %r', self)
+    logging.info('In format_for_template for %s',
+                 repr(self)[:settings.MAX_LOG_LINE])
     d = self.to_dict()
     is_released = self.impl_status_chrome in RELEASE_IMPL_STATES
     d['is_released'] = is_released

internals/notifier.py

@@ -226,7 +226,7 @@ class FeatureStar(models.DictModel):
     feature_stars = q.fetch(None)
     logging.info('found %d stars for %r', len(feature_stars), feature_id)
     emails = [fs.email for fs in feature_stars]
-    logging.info('looking up %r', emails)
+    logging.info('looking up %r', repr(emails)[:settings.MAX_LOG_LINE])
     user_prefs = models.UserPref.get_prefs_for_emails(emails)
     user_prefs = [up for up in user_prefs
                   if up.notify_as_starrer and not up.bounced]
@@ -245,7 +245,8 @@ class FeatureChangeHandler(basehandlers.FlaskHandler):
     is_update = self.get_bool_param('is_update')
     changes = self.get_param('changes', required=False) or []
 
-    logging.info('Starting to notify subscribers for feature %r', feature)
+    logging.info('Starting to notify subscribers for feature %s',
+                 repr(feature)[:settings.MAX_LOG_LINE])
 
     # Email feature subscribers if the feature exists and there were
     # actually changes to it.
@@ -265,6 +266,6 @@ class FeatureChangeHandler(basehandlers.FlaskHandler):
               'Subject: %s\n'
               'Body:\n%s',
               one_email_dict['to'], one_email_dict['subject'],
-              one_email_dict['html'])
+              one_email_dict['html'][:settings.MAX_LOG_LINE])
 
     return {'message': 'Done'}

internals/sendemail.py

@@ -70,7 +70,7 @@ def handle_outbound_mail_task():
   logging.info('Will send the following email:\n')
   logging.info('To: %s', message.to)
   logging.info('Subject: %s', message.subject)
-  logging.info('Body:\n%s', message.html)
+  logging.info('Body:\n%s', message.html[:settings.MAX_LOG_LINE])
   if settings.SEND_EMAIL:
     message.send()
     logging.info('Email sent')

settings.py

@@ -1,6 +1,3 @@
-
-
-
 import logging
 import os
 
@@ -47,6 +44,11 @@ DEV_MODE = (os.environ['SERVER_SOFTWARE'].startswith('Development') or
             os.environ.get('GAE_ENV', '').startswith('localdev'))
 UNIT_TEST_MODE = os.environ['SERVER_SOFTWARE'].startswith('test')
 
+if not UNIT_TEST_MODE:
+  # Py3 defaults to level WARN.
+  logging.basicConfig(level=logging.INFO)
+
+
 #setting GOOGLE_CLOUD_PROJECT manually in dev mode
 if DEV_MODE or UNIT_TEST_MODE:
   APP_ID = os.environ.get('GOOGLE_CLOUD_PROJECT', 'dev')
@@ -66,6 +68,9 @@ LOGIN_PAGE_URL = '/features?loginStatus=False'
 
 INBOUND_EMAIL_ADDR = 'chromestatus@cr-status-staging.appspotmail.com'
 
+# Truncate some log lines to stay under limits of Google Cloud Logging.
+MAX_LOG_LINE = 200 * 1000
+
 
 if UNIT_TEST_MODE:
   APP_TITLE = 'Local testing'

testing_config.py

@@ -109,4 +109,4 @@ class CustomTestCase(unittest.TestCase):
   def run(self, result=None):
     client = ndb.Client()
     with client.context():
-      super(CustomTestCase, self).run(result=result)
+      super(CustomTestCase, self).run(result=result)