From 3983e96e36797faf88bbc1800668fceb1fa60b46 Mon Sep 17 00:00:00 2001 From: Andrew Gorcester Date: Mon, 20 Jul 2015 15:44:00 -0700 Subject: [PATCH] Send structured logs to Cloud Logging --- multicore_runtime/cloud_logging.py | 74 +++++++++++++++++++++++ multicore_runtime/cloud_logging_test.py | 78 +++++++++++++++++++++++++ multicore_runtime/wsgi.py | 7 ++- 3 files changed, 158 insertions(+), 1 deletion(-) create mode 100644 multicore_runtime/cloud_logging.py create mode 100644 multicore_runtime/cloud_logging_test.py diff --git a/multicore_runtime/cloud_logging.py b/multicore_runtime/cloud_logging.py new file mode 100644 index 00000000..d1341d5a --- /dev/null +++ b/multicore_runtime/cloud_logging.py @@ -0,0 +1,74 @@ +# Copyright 2015 Google Inc. All Rights Reserved. +# +# Licensed under the Apache License, Version 2.0 (the "License"); +# you may not use this file except in compliance with the License. +# You may obtain a copy of the License at +# +# http://www.apache.org/licenses/LICENSE-2.0 +# +# Unless required by applicable law or agreed to in writing, software +# distributed under the License is distributed on an "AS IS" BASIS, +# WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. +# See the License for the specific language governing permissions and +# limitations under the License. +# +"""Provide a handler to log to Cloud Logging in JSON.""" + +import json +import logging +import math +import os + +LOG_PATH_TEMPLATE = '/var/log/app_engine/app.{}.json' + + +class CloudLoggingHandler(logging.FileHandler): + """A handler that emits logs to Cloud Logging. + + Writes to the Cloud Logging directory, wrapped in JSON and with appropriate + metadata. The process of converting the user's formatted logs into a JSON + payload for Cloud Logging consumption is implemented as part of the handler + itself, and not as a formatting step, so as not to interfere with user-defined + logging formats. + + The handler will look for HTTP header information in the environment (which + will be present in the GAE 1.0-compatible runtime) and, if it exists, will + parse the X-Cloud-Trace-Context header to add a Trace ID to each log record. + + Logging calls can also alternatively 'trace_id' in as a field in the 'extra' + dict, which will be used preferentially to fill out the Trace ID metadata. + """ + + def __init__(self): + # Large log entries will get mangled if multiple workers write to the same + # file simultaneously, so we'll use the worker's PID to pick a log filename. + filename = LOG_PATH_TEMPLATE.format(os.getpid()) + super(CloudLoggingHandler, self).__init__(filename, delay=True) + + def format(self, record): + """Format the specified record default behavior, plus JSON and metadata.""" + # First, let's just get the log string as it would normally be formatted. + message = super(CloudLoggingHandler, self).format(record) + + # Now assemble a dictionary with the log string as the message. + payload = { + 'message': message, + 'timestamp': {'seconds': int(record.created), + 'nanos': int(math.modf(record.created)[0] * 1000000000)}, + 'thread': record.thread, + 'severity': record.levelname,} + + # Now make a best effort to add the trace id. + # First, try to get the trace id from the 'extras' of the record. + trace_id = getattr(record, 'trace_id', None) + + # If that didn't work, check if HTTP headers are present in the + # environment (GAE 1.0-style), and use them to parse out the Trace ID. + if not trace_id: + trace_id = os.getenv('X-Cloud-Trace-Context', '')[:16] + + # Now add a traceID key to the payload, if one was found. + if trace_id: + payload['traceId'] = trace_id + + return json.dumps(payload) diff --git a/multicore_runtime/cloud_logging_test.py b/multicore_runtime/cloud_logging_test.py new file mode 100644 index 00000000..a4bb75fc --- /dev/null +++ b/multicore_runtime/cloud_logging_test.py @@ -0,0 +1,78 @@ +# Copyright 2015 Google Inc. All Rights Reserved. +# +# Licensed under the Apache License, Version 2.0 (the "License"); +# you may not use this file except in compliance with the License. +# You may obtain a copy of the License at +# +# http://www.apache.org/licenses/LICENSE-2.0 +# +# Unless required by applicable law or agreed to in writing, software +# distributed under the License is distributed on an "AS IS" BASIS, +# WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. +# See the License for the specific language governing permissions and +# limitations under the License. +# +import json +import logging +import mock +import os +import unittest + +import cloud_logging + + +class CloudLoggingTestCase(unittest.TestCase): + + EXPECTED_TRACE_ID = None + EXPECTED_OVERRIDDEN_TRACE_ID = '1234123412341234' + EXPECTED_MESSAGE = 'test message' + TEST_TIME = 1437589520.830589056 + EXPECTED_SECONDS = 1437589520 + EXPECTED_NANOS = 830589056 + + def setUp(self): + self.handler = cloud_logging.CloudLoggingHandler() + with mock.patch('time.time', return_value=self.TEST_TIME): + self.record = logging.makeLogRecord({'msg': self.EXPECTED_MESSAGE, + 'levelname': 'INFO'}) + self.record_with_extra = logging.makeLogRecord( + {'msg': self.EXPECTED_MESSAGE, + 'levelname': 'INFO', + 'trace_id': self.EXPECTED_OVERRIDDEN_TRACE_ID,}) + + def test_file_name_is_correct(self): + self.assertTrue(self.handler.baseFilename.startswith( + '/var/log/app_engine/app.')) + self.assertTrue(self.handler.baseFilename.endswith('.json')) + + def test_format(self): + msg = self.handler.format(self.record) + payload = json.loads(msg) + if self.EXPECTED_TRACE_ID: + self.assertEquals(payload['traceId'], self.EXPECTED_TRACE_ID) + else: + self.assertNotIn('traceId', payload) + + def test_format_with_trace_id_as_extra(self): + msg = self.handler.format(self.record_with_extra) + payload = json.loads(msg) + self.assertEquals(payload['traceId'], self.EXPECTED_OVERRIDDEN_TRACE_ID) + + def test_format_timestamp(self): + msg = self.handler.format(self.record) + payload = json.loads(msg) + self.assertEquals(payload['timestamp']['seconds'], self.EXPECTED_SECONDS) + self.assertEquals(payload['timestamp']['nanos'], self.EXPECTED_NANOS) + + +class CloudLoggingTestCaseWithTraceIdEnv(CloudLoggingTestCase): + + EXPECTED_TRACE_ID = '0101010102020202' + + def setUp(self): + super(CloudLoggingTestCaseWithTraceIdEnv, self).setUp() + os.environ['X-Cloud-Trace-Context'] = '{}/12345;o=1'.format( + self.EXPECTED_TRACE_ID) + + def tearDown(self): + os.unsetenv('X-Cloud-Trace-Context') diff --git a/multicore_runtime/wsgi.py b/multicore_runtime/wsgi.py index 633fbde1..af5fad6f 100644 --- a/multicore_runtime/wsgi.py +++ b/multicore_runtime/wsgi.py @@ -23,6 +23,7 @@ import logging import os +import cloud_logging from dispatcher import dispatcher from middleware import health_check_middleware from middleware import reset_environment_middleware @@ -36,8 +37,12 @@ from google.appengine.ext.vmruntime import vmconfig from google.appengine.ext.vmruntime import vmstub -logging.basicConfig(level=logging.INFO) +# Configure logging to output structured JSON to Cloud Logging. +handler = cloud_logging.CloudLoggingHandler() +handler.setLevel(logging.INFO) +logging.getLogger('').addHandler(handler) +# Fetch application configuration via the config file. appinfo = get_module_config(get_module_config_filename()) env_config = vmconfig.BuildVmAppengineEnvConfig()